Bug 1520 - Samba3 SEGV's in printer_notify_info for SPOOLSS_RFNPCNEX on WinXP SP2 RC2
Samba3 SEGV's in printer_notify_info for SPOOLSS_RFNPCNEX on WinXP SP2 RC2
Status: CLOSED FIXED
Product: Samba 3.0
Classification: Unclassified
Component: Printing
3.0.5
x86 Windows XP
: P3 major
: none
Assigned To: Gerald (Jerry) Carter
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2004-07-12 21:14 UTC by Craig A. Huegen
Modified: 2005-08-24 10:24 UTC (History)
0 users

See Also:


Attachments
check option pointer before dereferencing it. (776 bytes, patch)
2004-07-13 12:17 UTC, Gerald (Jerry) Carter
no flags Details

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 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 2004-07-13 12:17:40 UTC
Created attachment 564 [details]
check option pointer before dereferencing it.
Comment 4 Gerald (Jerry) Carter 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 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 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 2005-08-24 10:24:27 UTC
sorry for the same, cleaning up the database to prevent unecessary reopens of bugs.