1520 – Samba3 SEGV's in printer_notify_info for SPOOLSS_RFNPCNEX on WinXP SP2 RC2

Bug 1520 - Samba3 SEGV's in printer_notify_info for SPOOLSS_RFNPCNEX on WinXP SP2 RC2

Summary: Samba3 SEGV's in printer_notify_info for SPOOLSS_RFNPCNEX on WinXP SP2 RC2

Status:	CLOSED FIXED

Alias:	None

Product:	Samba 3.0
Classification:	Unclassified
Component:	Printing (show other bugs)
Version:	3.0.5
Hardware:	x86 Windows XP

Importance:	P3 major
Target Milestone:	none
Assignee:	Gerald (Jerry) Carter (dead mail address)
QA Contact:	Samba QA Contact

URL:
Keywords:

Depends on:
Blocks:

Reported:	2004-07-12 21:14 UTC by Craig A. Huegen
Modified:	2005-08-24 10:24 UTC (History)
CC List:	0 users

See Also:

Attachments
check option pointer before dereferencing it. (776 bytes, patch) 2004-07-13 12:17 UTC, Gerald (Jerry) Carter (dead mail address)	no flags	Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Craig A. Huegen 2004-07-12 21:14:56 UTC

Upgrading to Windows XP SP2 (RC2) has broken printing to my Samba-based 
printers on FreeBSD 4.10, causing a core dump in printer_notify_info for the 
spoolss rfnpcnex call.

This occurs when I am trying to print anything to my magicolor 2300DL printer 
from any application on the Windows XP machine.  This does not happen with my 
Windows XP machines with SP1.

I searched and did not find any comparable bugs.

Stack dump:

Program received signal SIGSEGV, Segmentation fault.
0x8136ffa in printer_notify_info (p=0x839a000, hnd=0xbfbff490, 
    info=0xbfbff47c, mem_ctx=0x82ea870) at rpc_server/srv_spoolss_nt.c:3792
3792            for (i=0; i<option->count; i++) {
(gdb) bt
#0  0x8136ffa in printer_notify_info (p=0x839a000, hnd=0xbfbff490, 
    info=0xbfbff47c, mem_ctx=0x82ea870) at rpc_server/srv_spoolss_nt.c:3792
#1  0x81373bb in _spoolss_rfnpcnex (p=0x839a000, q_u=0xbfbff490, 
    r_u=0xbfbff478) at rpc_server/srv_spoolss_nt.c:3893
#2  0x812b38c in api_spoolss_rfnpcnex (p=0x839a000)
    at rpc_server/srv_spoolss.c:337
#3  0x81623d1 in api_rpcTNP (p=0x839a000, rpc_name=0x839a00e "spoolss", 
    api_rpc_cmds=0x82cdfa4, n_cmds=51) at rpc_server/srv_pipe.c:1559
#4  0x8162056 in api_pipe_request (p=0x839a000) at rpc_server/srv_pipe.c:1505
#5  0x815ace0 in process_request_pdu (p=0x839a000, rpc_in_p=0xbfbff68c)
    at rpc_server/srv_pipe_hnd.c:669
#6  0x815af80 in process_complete_pdu (p=0x839a000)
    at rpc_server/srv_pipe_hnd.c:741
#7  0x815b2ec in process_incoming_data (p=0x839a000, data=0x834a190 ",", n=52)
    at rpc_server/srv_pipe_hnd.c:839
#8  0x815b541 in write_to_internal_pipe (np_conn=0x839a000, 
    data=0x834a190 ",", n=68) at rpc_server/srv_pipe_hnd.c:878
#9  0x815b499 in write_to_pipe (p=0x8351200, data=0x834a180 "\005", n=68)
    at rpc_server/srv_pipe_hnd.c:861
#10 0x8088ce8 in api_fd_reply (conn=0x834d000, vuid=100, outbuf=0x8373000 "", 
    setup=0x832f140, data=0x834a180 "\005", params=0x0, suwcnt=2, tdscnt=68, 
    tpscnt=0, mdrcnt=4280, mprcnt=0) at smbd/ipc.c:306
#11 0x8088fa2 in named_pipe (conn=0x834d000, vuid=100, outbuf=0x8373000 "", 
    name=0xbfbff896 "", setup=0x832f140, data=0x834a180 "\005", params=0x0, 
    suwcnt=2, tdscnt=68, tpscnt=0, msrcnt=0, mdrcnt=4280, mprcnt=0)
    at smbd/ipc.c:350
#12 0x8089e3f in reply_trans (conn=0x834d000, inbuf=0x8352000 "", 
    outbuf=0x8373000 "", size=156, bufsize=131072) at smbd/ipc.c:558
#13 0x80d5fed in switch_message (type=37, inbuf=0x8352000 "", 
    outbuf=0x8373000 "", size=156, bufsize=131072) at smbd/process.c:969
#14 0x80d60bf in construct_reply (inbuf=0x8352000 "", outbuf=0x8373000 "", 
    size=156, bufsize=131072) at smbd/process.c:999
#15 0x80d6467 in process_smb (inbuf=0x8352000 "", outbuf=0x8373000 "")
    at smbd/process.c:1099
#16 0x80d728d in smbd_process () at smbd/process.c:1556
#17 0x824c17f in main (argc=2, argv=0xbfbffc1c) at smbd/server.c:907
(gdb) print option
$1 = (SPOOL_NOTIFY_OPTION *) 0x0

Debug level 10 output:

[2004/07/12 22:55:16, 10] lib/util_sock.c:read_smb_length_return_keepalive(505)
  got smb length of 152
[2004/07/12 22:55:16, 6] smbd/process.c:process_smb(1091)
  got message type 0x0 of len 0x98
[2004/07/12 22:55:16, 3] smbd/process.c:process_smb(1092)
  Transaction 641 of length 156
[2004/07/12 22:55:16, 5] lib/util.c:show_msg(443)
[2004/07/12 22:55:16, 5] lib/util.c:show_msg(453)
  size=152
  smb_com=0x25
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51207
  smb_tid=1
  smb_pid=1740
  smb_uid=100
  smb_mid=41025
  smt_wct=16
  smb_vwv[ 0]=    0 (0x0)
  smb_vwv[ 1]=   68 (0x44)
  smb_vwv[ 2]=    0 (0x0)
  smb_vwv[ 3]= 4280 (0x10B8)
  smb_vwv[ 4]=    0 (0x0)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=    0 (0x0)
  smb_vwv[ 7]=    0 (0x0)
  smb_vwv[ 8]=    0 (0x0)
  smb_vwv[ 9]=    0 (0x0)
  smb_vwv[10]=   84 (0x54)
  smb_vwv[11]=   68 (0x44)
  smb_vwv[12]=   84 (0x54)
  smb_vwv[13]=    2 (0x2)
  smb_vwv[14]=   38 (0x26)
  smb_vwv[15]=28930 (0x7102)
  smb_bcc=85
[2004/07/12 22:55:16, 10] lib/util.c:dump_data(1839)
  [000] 00 5C 00 50 00 49 00 50  00 45 00 5C 00 00 00 00  .\.P.I.P .E.\....
  [010] 00 05 00 00 03 10 00 00  00 44 00 00 00 B6 01 00  ........ .D......
  [020] 00 2C 00 00 00 00 00 43  00 00 00 00 00 90 00 00  .,.....C ........
  [030] 00 00 00 00 00 24 5D F3  40 F1 F5 00 00 01 00 00  .....$]. @.......
  [040] 00 44 24 0A 00 02 00 00  00 01 00 00 00 00 00 00  .D$..... ........
  [050] 00 00 00 00 00                                    ..... 
[2004/07/12 22:55:16, 3] smbd/process.c:switch_message(887)
  switch message SMBtrans (pid 62961) conn 0x834d000
[2004/07/12 22:55:16, 4] smbd/uid.c:change_to_user(193)
  change_to_user: Skipping user change - already user
[2004/07/12 22:55:16, 3] smbd/ipc.c:reply_trans(538)
  trans <\PIPE\> data=68 params=0 setup=2
[2004/07/12 22:55:16, 5] smbd/ipc.c:reply_trans(557)
  calling named_pipe
[2004/07/12 22:55:16, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2004/07/12 22:55:16, 5] smbd/ipc.c:api_fd_reply(267)
  api_fd_reply
[2004/07/12 22:55:16, 4] rpc_server/srv_pipe_hnd.c:get_rpc_pipe(1157)
  search for pipe pnum=7102
[2004/07/12 22:55:16, 5] rpc_server/srv_pipe_hnd.c:get_rpc_pipe(1161)
  pipe name spoolss pnum=7106 (pipes_open=5)
[2004/07/12 22:55:16, 5] rpc_server/srv_pipe_hnd.c:get_rpc_pipe(1161)
  pipe name spoolss pnum=7105 (pipes_open=5)
[2004/07/12 22:55:16, 5] rpc_server/srv_pipe_hnd.c:get_rpc_pipe(1161)
  pipe name spoolss pnum=7104 (pipes_open=5)
[2004/07/12 22:55:16, 5] rpc_server/srv_pipe_hnd.c:get_rpc_pipe(1161)
  pipe name spoolss pnum=7103 (pipes_open=5)
[2004/07/12 22:55:16, 5] rpc_server/srv_pipe_hnd.c:get_rpc_pipe(1161)
  pipe name spoolss pnum=7102 (pipes_open=5)
[2004/07/12 22:55:16, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 7102)
[2004/07/12 22:55:16, 10] smbd/ipc.c:api_fd_reply(301)
  api_fd_reply: p:0x8351000 max_trans_reply: 4280
[2004/07/12 22:55:16, 6] rpc_server/srv_pipe_hnd.c:write_to_pipe(854)
  write_to_pipe: 7102 name: spoolss open: Yes len: 68
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:write_to_internal_pipe(876)
  write_to_pipe: data_left = 68
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:process_incoming_data(779)
  process_incoming_data: Start: pdu_received_len = 0, pdu_needed_len = 0, 
incoming data = 68
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:fill_rpc_header(401)
  fill_rpc_header: data_to_copy = 68, len_needed_to_complete_hdr = 16, 
receive_len = 0
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:write_to_internal_pipe(880)
  write_to_pipe: data_used = 16
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:write_to_internal_pipe(876)
  write_to_pipe: data_left = 52
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:process_incoming_data(779)
  process_incoming_data: Start: pdu_received_len = 16, pdu_needed_len = 0, 
incoming data = 52
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_debug(82)
  000000 smb_io_rpc_hdr 
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0000 major     : 05
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0001 minor     : 00
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0002 pkt_type  : 00
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0003 flags     : 03
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0004 pack_type0: 10
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0005 pack_type1: 00
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0006 pack_type2: 00
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8(577)
      0007 pack_type3: 00
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint16(606)
      0008 frag_len  : 0044
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint16(606)
      000a auth_len  : 0000
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
      000c call_id   : 000001b6
[2004/07/12 22:55:16, 5] rpc_server/srv_pipe_hnd.c:unmarshall_rpc_header(488)
  unmarshall_rpc_header: using little-endian RPC
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:unmarshall_rpc_header(517)
  unmarshall_rpc_header: type = 0, flags = 3
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:write_to_internal_pipe(880)
  write_to_pipe: data_used = 0
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:write_to_internal_pipe(876)
  write_to_pipe: data_left = 52
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:process_incoming_data(779)
  process_incoming_data: Start: pdu_received_len = 0, pdu_needed_len = 52, 
incoming data = 52
[2004/07/12 22:55:16, 10] rpc_server/srv_pipe_hnd.c:process_complete_pdu(722)
  process_complete_pdu: processing packet type 0
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_debug(82)
  000000 smb_io_rpc_hdr_req req
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
      0000 alloc_hint: 0000002c
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint16(606)
      0004 context_id: 0000
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint16(606)
      0006 opnum     : 0043
[2004/07/12 22:55:16, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(544)
  free_pipe_context: destroying talloc pool of size 0
[2004/07/12 22:55:16, 5] rpc_server/srv_pipe.c:api_pipe_request(1497)
  Requested \PIPE\spoolss
[2004/07/12 22:55:16, 4] rpc_server/srv_pipe.c:api_rpcTNP(1531)
  api_rpcTNP: spoolss op 0x43 - api_rpcTNP: rpc command: SPOOLSS_RFNPCNEX
[2004/07/12 22:55:16, 6] rpc_server/srv_pipe.c:api_rpcTNP(1557)
  api_rpc_cmds[7].fn == 0x812b2b4
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_debug(82)
  000000 spoolss_io_q_rfnpcnex 
[2004/07/12 22:55:16, 6] rpc_parse/parse_prs.c:prs_debug(82)
      000000 smb_io_pol_hnd printer handle
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
          0000 data1: 00000000
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
          0004 data2: 00000090
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint16(606)
          0008 data3: 0000
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint16(606)
          000a data4: 0000
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint8s(722)
          000c data5: 24 5d f3 40 f1 f5 00 00 
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
      0014 change: 00000001
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
      0018 option_ptr: 000a2444
[2004/07/12 22:55:16, 6] rpc_parse/parse_prs.c:prs_debug(82)
      00001c smb_io_notify_option notify option
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
          001c version: 00000002
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
          0020 flags: 00000001
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
          0024 count: 00000000
[2004/07/12 22:55:16, 5] rpc_parse/parse_prs.c:prs_uint32(635)
          0028 option_type_ptr: 00000000
[2004/07/12 22:55:16, 4] rpc_server/srv_lsa_hnd.c:find_policy_by_hnd_internal
(162)
  Found policy hnd[2] [000] 00 00 00 00 90 00 00 00  00 00 00 00 24 5D F3 
40  ........ ....$].@
  [010] F1 F5 00 00                                       .... 
[2004/07/12 22:55:16, 4] rpc_server/srv_spoolss_nt.c:_spoolss_rfnpcnex(3866)
  Printer type 0
[2004/07/12 22:55:16, 4] rpc_server/srv_lsa_hnd.c:find_policy_by_hnd_internal
(162)
  Found policy hnd[2] [000] 00 00 00 00 90 00 00 00  00 00 00 00 24 5D F3 
40  ........ ....$].@
  [010] F1 F5 00 00                                       .... 
[2004/07/12 22:55:16, 4] rpc_server/srv_spoolss_nt.c:printer_notify_info(3779)
  printer_notify_info
[2004/07/12 22:55:16, 4] rpc_server/srv_lsa_hnd.c:find_policy_by_hnd_internal
(162)
  Found policy hnd[2] [000] 00 00 00 00 90 00 00 00  00 00 00 00 24 5D F3 
40  ........ ....$].@
  [010] F1 F5 00 00                                       .... 
[2004/07/12 22:55:16, 4] rpc_server/srv_spoolss_nt.c:get_printer_snum(431)
  short name:electric-eel
[2004/07/12 22:55:16, 0] lib/fault.c:fault_report(36)
  ===============================================================
[2004/07/12 22:55:16, 0] lib/fault.c:fault_report(37)
  INTERNAL ERROR: Signal 11 in pid 62961 (3.0.5rc1)
  Please read the appendix Bugs of the Samba HOWTO collection
[2004/07/12 22:55:16, 0] lib/fault.c:fault_report(39)
  ===============================================================
[2004/07/12 22:55:16, 0] lib/util.c:smb_panic2(1385)
  PANIC: internal error
[2004/07/12 22:55:16, 0] smbd/server.c:open_sockets_smbd(383)
  open_sockets_smbd: accept: Software caused connection abort
[2004/07/12 22:55:16, 0] param/loadparm.c:service_ok(2628)
  No path in service moray - using /tmp
[2004/07/12 22:55:16, 0] param/loadparm.c:service_ok(2628)
  No path in service electric-eel - using /tmp
[2004/07/12 22:55:16, 0] lib/fault.c:fault_report(36)
  ===============================================================
[2004/07/12 22:55:16, 0] lib/fault.c:fault_report(37)
  INTERNAL ERROR: Signal 11 in pid 62972 (3.0.5rc1)
  Please read the appendix Bugs of the Samba HOWTO collection
[2004/07/12 22:55:16, 0] lib/fault.c:fault_report(39)
  ===============================================================
[2004/07/12 22:55:16, 0] lib/util.c:smb_panic2(1385)
  PANIC: internal error
[2004/07/12 22:55:16, 0] lib/util_sock.c:set_socket_options(202)
  Failed to set socket option TCP_NODELAY (Error Connection reset by peer)
[2004/07/12 22:55:16, 0] lib/util_sock.c:get_peer_addr(1000)
  getpeername failed. Error was Socket is not connected

Comment 1 Craig A. Huegen 2004-07-12 21:20:44 UTC

I forgot to note that this occurs in Samba 3.0.2a, 3.0.4, and 3.0.5-RC1 (the 
versions I've all tried today).

Comment 2 Gerald (Jerry) Carter (dead mail address) 2004-07-13 12:17:10 UTC

This appears to be a bug in xp sp2 rc2.  The xp client sends a 
find_next_print_change_notify request without ever sending 
a find_first.

this patch causes smbd to return the same thing as 2k sp 4.

Comment 3 Gerald (Jerry) Carter (dead mail address) 2004-07-13 12:17:40 UTC

Created attachment 564 [details]
check option pointer before dereferencing it.

Comment 4 Gerald (Jerry) Carter (dead mail address) 2004-07-13 12:18:38 UTC

fixed.

Comment 5 Troels Walsted Hansen 2004-08-25 12:46:32 UTC

I don't want to be a party pooper, but the attached patch doesn't appear to be a
complete solution. :-(

I was experiencing the samba panics, so I took the patch and built a new RPM for
my RHEL3 server. RHEL3 uses Samba 3.0.4 with a few additional patches.

The panics disappeared, but a new problem came up. Printing works fine, but
documents are never removed from the print queue, I have to delete them manually
to make them go away.

I print through cups, to a Canon i850 printer.

Relevant Samba settings:

[global]
        printcap name = cups
        printing = cups
        print command = lpr -l -r -P%p %s
[printers]
        comment = All Printers
        path = /var/spool/samba
        printer admin = troels, tina
        printable = Yes
        browseable = No

Any ideas?

Comment 6 Craig A. Huegen 2004-08-25 17:51:36 UTC

I can confirm that this patch works successfully for both my HP LaserJet 4000N 
and my Konica-Minolta-QMS magicolor 2300DL printer shares, so you may have a 
different bug that needs to be fixed.

Comment 7 Gerald (Jerry) Carter (dead mail address) 2004-08-25 19:19:44 UTC

totally different bug.  XP sp2 breaks print change notify 
(even in all windows environments).  If you feel that there 
is a legitimate Samba bug, please open a new report.

Comment 8 Troels Walsted Hansen 2004-08-26 13:42:43 UTC

I guess you're right. I changed to print directly to CUPS through IPP and it
exhibited the same symptoms. :-( Sorry for the noise...

Comment 9 Gerald (Jerry) Carter (dead mail address) 2005-02-07 09:56:02 UTC

originally against 3.0.5rc1 (which was 34.0.6rc1 due to the security release).

Comment 10 Gerald (Jerry) Carter (dead mail address) 2005-08-24 10:24:27 UTC

sorry for the same, cleaning up the database to prevent unecessary reopens of bugs.