Bug 8384 - Windows XP clients seem to crash smbd process every once in a while
Summary: Windows XP clients seem to crash smbd process every once in a while
Status: RESOLVED FIXED
Alias: None
Product: Samba 3.6
Classification: Unclassified
Component: Printing (show other bugs)
Version: 3.6.0
Hardware: All All
: P5 regression
Target Milestone: ---
Assignee: Karolin Seeger
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks: 8399
  Show dependency treegraph
 
Reported: 2011-08-19 05:57 UTC by Martijn Berger
Modified: 2011-11-09 18:44 UTC (History)
6 users (show)

See Also:


Attachments
Sequnce of patches to apply to 3.6.1 to make the talloc library up to date with master. (22.97 KB, patch)
2011-08-19 18:01 UTC, Jeremy Allison
idra: review+
Details
Raw patch for 3.6.x. (3.33 KB, patch)
2011-10-24 19:08 UTC, Jeremy Allison
no flags Details
git-am fix that went into master (4.08 KB, patch)
2011-10-24 21:47 UTC, Jeremy Allison
no flags Details
Raw patch on top of attachment 7028. (583 bytes, patch)
2011-10-25 16:46 UTC, Jeremy Allison
no flags Details
Fix double-free caused by calling srv_spoolss_replycloseprinter twice. (467 bytes, patch)
2011-10-29 16:37 UTC, Henry Wong
no flags Details
git-am fix for 3.6.next. (1.06 KB, patch)
2011-11-04 21:41 UTC, Jeremy Allison
jra: review? (gd)
metze: review+
asn: review+
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Martijn Berger 2011-08-19 05:57:33 UTC
The crash happens infrequently on vanilla samba 3.6.0 compiled for ubuntu lucid. 
It seems to relate to windows XP printing as far as I can tell at this moment.

About 5 windows xp guests active would lead to 2-3 crashes a day. I am looking into this further but dont know what steps to take next as I am unable to reproduce the problem at this time.

[Thread debugging using libthread_db enabled]
0x00007f014342cf7e in waitpid () from /lib/libc.so.6
#0  0x00007f014342cf7e in waitpid () from /lib/libc.so.6
#1  0x00007f01433c47e9 in ?? () from /lib/libc.so.6
#2  0x00007f0146a00ad7 in smb_panic ()
#3  0x00007f01469f18e4 in ?? ()
#4  <signal handler called>
#5  0x00007f0146a7276d in dcerpc_binding_handle_call ()
#6  0x00007f014691a4ad in dcerpc_spoolss_ReplyClosePrinter_r ()
#7  0x00007f014691a4d8 in dcerpc_spoolss_ReplyClosePrinter ()
#8  0x00007f01468b69ef in ?? ()
#9  0x00007f01468b6e2c in ?? ()
#10 0x00007f0143d3f082 in ?? () from /usr/lib/libtalloc.so.2
#11 0x00007f0143d3ef0b in ?? () from /usr/lib/libtalloc.so.2
#12 0x00007f0143d3dd7b in _talloc_free () from /usr/lib/libtalloc.so.2
#13 0x00007f0146903a5c in close_policy_by_pipe ()
#14 0x00007f0146903540 in close_internal_rpc_pipe_hnd ()
#15 0x00007f0143d3f082 in ?? () from /usr/lib/libtalloc.so.2
#16 0x00007f0143d3dd7b in _talloc_free () from /usr/lib/libtalloc.so.2
#17 0x00007f01466e80b4 in file_free ()
#18 0x00007f0146765c19 in close_fake_file ()
#19 0x00007f01467446a5 in close_file ()
#20 0x00007f01466e885c in file_close_conn ()
#21 0x00007f014675d44c in close_cnum ()
#22 0x00007f01466efc84 in conn_close_all ()
#23 0x00007f0146c757b9 in ?? ()
#24 0x00007f0146c75a4e in exit_server_cleanly ()
#25 0x00007f014675cc88 in ?? ()
#26 0x00007f0146a0fc89 in run_events_poll ()
#27 0x00007f014675a50d in smbd_process ()
#28 0x00007f0146c73def in ?? ()
#29 0x00007f0146a0fc89 in run_events_poll ()
#30 0x00007f0146a1012f in ?? ()
#31 0x00007f0146a104b0 in _tevent_loop_once ()
#32 0x00007f0146c751b3 in main ()
A debugging session is active.
Comment 1 Andreas Schneider 2011-08-19 10:44:12 UTC
Martijn: Could you please install debuginfo packages for samba and talloc. If it crashes you should see a short backtrace and a full backtrace in the log file. Wee need the full backtrace.


Günther: This looks like the talloc bug we fixed lately?

cf986f200804ce873b43c1ecf2d5e1bd08eb8a25
Comment 2 Jeremy Allison 2011-08-19 15:37:18 UTC
Yes, I think this is the talloc bug. I''ll add Simo so he can attach his talloc backport to 3.5.12 and 3.6.0 here.

Jeremy.
Comment 3 Jeremy Allison 2011-08-19 18:01:36 UTC
Created attachment 6792 [details]
Sequnce of patches to apply to 3.6.1 to make the talloc library up to date with master.

Simo - here are is the patch sequence that makes talloc in 3.6.1 identical to talloc in master.

Please review.

Jeremy.
Comment 4 Simo Sorce 2011-08-19 19:33:52 UTC
(In reply to comment #3)
> Created attachment 6792 [details]
> Sequnce of patches to apply to 3.6.1 to make the talloc library up to date with
> master.
> 
> Simo - here are is the patch sequence that makes talloc in 3.6.1 identical to
> talloc in master.
> 
> Please review.
> 
> Jeremy.

Yep this looks like another manifestation of the talloc bug.
Patches looks good feel free to push for 3.6.1
Comment 5 Simo Sorce 2011-08-19 19:34:10 UTC
Comment on attachment 6792 [details]
Sequnce of patches to apply to 3.6.1 to make the talloc library up to date with master.

Ack on patches
Comment 6 Jeremy Allison 2011-08-19 19:37:23 UTC
Re-assigning to Karolin for inclusion in 3.6.1.

Jeremy.
Comment 7 Martijn Berger 2011-08-20 07:53:22 UTC
I may or may not be to blame since I compiled it agains a backported libtalloc (tdb - 1.2.9-1fakesync1) one that Jelmer made for natty I think.

Ill make a package for libtalloc 2.0.6 and rebuild it agains that and report.
Comment 8 Martijn Berger 2011-08-20 08:09:51 UTC
(In reply to comment #7)
> I may or may not be to blame since I compiled it agains a backported libtalloc
> (tdb - 1.2.9-1fakesync1) one that Jelmer made for natty I think.
> 
> Ill make a package for libtalloc 2.0.6 and rebuild it agains that and report.

I am confusing my tdb's and talloc's here a bit I think i need to package up to date versions of both to be able to run with Ubuntu 10.04. 

I am going to make debs for those as-well and then roll out a new samba 3.6 build compiled against that. If the problem resists Ill then apply the patch in this issue.

I need 1-2 days to know if the problem happens, so Ill know by Thursday 19:00 UTC.

Hope I did not bring work upon you, when I should have put more time into what samba's actual decencies are and how debian/ubuntu packages them.
Comment 9 Karolin Seeger 2011-08-20 18:58:09 UTC
(In reply to comment #6)
> Re-assigning to Karolin for inclusion in 3.6.1.
> 
> Jeremy.

Pushed to v3-6-test.
Closing out bug report.
Martijn, please feel free to re-open if it's still an issue.

Thanks!
Comment 10 Martijn Berger 2011-09-23 07:53:48 UTC
I move to libtalloc2 2.0.7 and rebuild samba against that but I still the crashes sometimes:


[Thread debugging using libthread_db enabled]
0x00007ff18cf79f7e in waitpid () from /lib/libc.so.6
#0  0x00007ff18cf79f7e in waitpid () from /lib/libc.so.6
#1  0x00007ff18cf117e9 in ?? () from /lib/libc.so.6
#2  0x00007ff19054ec17 in smb_panic ()
#3  0x00007ff19053fa24 in ?? ()
#4  <signal handler called>
#5  0x00007ff1905c08ad in dcerpc_binding_handle_call ()
#6  0x00007ff1904685ed in dcerpc_spoolss_ReplyClosePrinter_r ()
#7  0x00007ff190468618 in dcerpc_spoolss_ReplyClosePrinter ()
#8  0x00007ff190404b2f in ?? ()
#9  0x00007ff190404f6c in ?? ()
#10 0x00007ff18d88b4b4 in ?? () from /usr/lib/libtalloc.so.2
#11 0x00007ff18d88b233 in ?? () from /usr/lib/libtalloc.so.2
#12 0x00007ff18d88b233 in ?? () from /usr/lib/libtalloc.so.2
#13 0x00007ff190451b9c in close_policy_by_pipe ()
#14 0x00007ff190451680 in close_internal_rpc_pipe_hnd ()
#15 0x00007ff18d88b4b4 in ?? () from /usr/lib/libtalloc.so.2
#16 0x00007ff18d88b233 in ?? () from /usr/lib/libtalloc.so.2
#17 0x00007ff1902360e4 in file_free ()
#18 0x00007ff1902b3d89 in close_fake_file ()
#19 0x00007ff190292815 in close_file ()
#20 0x00007ff19023688c in file_close_conn ()
#21 0x00007ff1902ab5bc in close_cnum ()
#22 0x00007ff19023dcb4 in conn_close_all ()
#23 0x00007ff1907c38f9 in ?? ()
#24 0x00007ff1907c3b8e in exit_server_cleanly ()
#25 0x00007ff1902aadf8 in ?? ()
#26 0x00007ff19055ddc9 in run_events_poll ()
#27 0x00007ff1902a867d in smbd_process ()
#28 0x00007ff1907c1f2f in ?? ()
#29 0x00007ff19055ddc9 in run_events_poll ()
#30 0x00007ff19055e26f in ?? ()
#31 0x00007ff19055e5f0 in _tevent_loop_once ()
#32 0x00007ff1907c32f3 in main ()
A debugging session is active.
Comment 11 Andreas Schneider 2011-09-23 08:02:36 UTC
Can you please install/build with debug symbols and provide a full backtrace?
Comment 12 Karolin Seeger 2011-09-26 18:34:28 UTC
Jeremy, is this a showstopper for 3.6.1?
Comment 13 Jeremy Allison 2011-09-26 23:08:39 UTC
This is not a blocker for 3.6.1 (IMHO). Only one reporter and not yet clear it's reproducible.
Jeremy.
Comment 14 Alejandro Escanero Blanco 2011-10-05 09:33:31 UTC
I have the same problem with 3.6.0 in my printer servers, my log is:
[2011/10/04 11:34:14.896485,  0, effective(875111, 2038), real(0, 0)] lib/util.c:1116(smb_panic)
  PANIC (pid 7067): internal error
[2011/10/04 11:34:14.906499,  0, effective(875111, 2038), real(0, 0)] lib/util.c:1220(log_stack_trace)
  BACKTRACE: 35 stack frames:
   #0 /usr/local/samba/sbin/smbd(log_stack_trace+0x2d) [0xa90655]
   #1 /usr/local/samba/sbin/smbd(smb_panic+0x7c) [0xa90787]
   #2 /usr/local/samba/sbin/smbd [0xa80e0e]
   #3 [0x34d420]
   #4 /usr/local/samba/sbin/smbd(dcerpc_spoolss_ReplyClosePrinter_r+0x54) [0x98d849]
   #5 /usr/local/samba/sbin/smbd(dcerpc_spoolss_ReplyClosePrinter+0x43) [0x98d8a2]
   #6 /usr/local/samba/sbin/smbd [0x924d7a]
   #7 /usr/local/samba/sbin/smbd [0x92517a]
   #8 /usr/local/samba/lib/libtalloc.so.2 [0x2d689e]
   #9 /usr/local/samba/lib/libtalloc.so.2 [0x2d6a21]
   #10 /usr/local/samba/lib/libtalloc.so.2(_talloc_free+0xd8) [0x2d73ee]
   #11 /usr/local/samba/sbin/smbd(close_policy_hnd+0x15f) [0x974691]
   #12 /usr/local/samba/sbin/smbd [0x923c7a]
   #13 /usr/local/samba/sbin/smbd(_spoolss_ClosePrinter+0x5a) [0x929a5f]
   #14 /usr/local/samba/sbin/smbd [0x93dd52]
   #15 /usr/local/samba/sbin/smbd [0x96f42a]
   #16 /usr/local/samba/sbin/smbd(process_complete_pdu+0x295) [0x96fa85]
   #17 /usr/local/samba/sbin/smbd(process_incoming_data+0x401) [0x971ca4]
   #18 /usr/local/samba/sbin/smbd(np_write_send+0x16f) [0x971e95]
   #19 /usr/local/samba/sbin/smbd [0x73a5fa]
   #20 /usr/local/samba/sbin/smbd [0x73ac2c]
   #21 /usr/local/samba/sbin/smbd(reply_trans+0x70f) [0x73b8c5]
   #22 /usr/local/samba/sbin/smbd [0x7a2ab8]
   #23 /usr/local/samba/sbin/smbd [0x7a6bd8]
   #24 /usr/local/samba/sbin/smbd [0x7a6eb3]
   #25 /usr/local/samba/sbin/smbd [0x7a6f51]
   #26 /usr/local/samba/sbin/smbd(run_events_poll+0x41c) [0xa9fee3]
   #27 /usr/local/samba/sbin/smbd(smbd_process+0x1544) [0x7a5bbb]
   #28 /usr/local/samba/sbin/smbd [0xd824d8]
   #29 /usr/local/samba/sbin/smbd(run_events_poll+0x41c) [0xa9fee3]
   #30 /usr/local/samba/sbin/smbd [0xaa0344]
   #31 /usr/local/samba/sbin/smbd(_tevent_loop_once+0x9d) [0xaa079d]
   #32 /usr/local/samba/sbin/smbd(main+0x1715) [0xd84101]
   #33 /lib/libc.so.6(__libc_start_main+0xdc) [0x41de9c]
   #34 /usr/local/samba/sbin/smbd [0x71e9e1]
[2011/10/04 11:34:14.910793,  0, effective(0, 0), real(0, 0)] lib/fault.c:372(dump_core)
  dumping core in /var/log/samba/cores/smbd

A bt is:
#0  0x0034d402 in __kernel_vsyscall ()
#1  0x00430df0 in raise () from /lib/libc.so.6
#2  0x00432701 in abort () from /lib/libc.so.6
#3  0x00a80840 in dump_core ()
#4  0x00a908ae in smb_panic ()
#5  0x00a80e0e in sig_fault ()
#6  <signal handler called>
#7  0x00b09458 in dcerpc_binding_handle_call ()
#8  0x0098d849 in dcerpc_spoolss_ReplyClosePrinter_r ()
#9  0x0098d8a2 in dcerpc_spoolss_ReplyClosePrinter ()
#10 0x00924d7a in srv_spoolss_replycloseprinter ()
#11 0x0092517a in printer_entry_destructor ()
#12 0x002d689e in _talloc_free_internal () from /usr/local/samba/lib/libtalloc.so.2
#13 0x002d6a21 in _talloc_free_internal () from /usr/local/samba/lib/libtalloc.so.2
#14 0x002d73ee in _talloc_free () from /usr/local/samba/lib/libtalloc.so.2
#15 0x00974691 in close_policy_hnd ()
#16 0x00923c7a in close_printer_handle ()
#17 0x00929a5f in _spoolss_ClosePrinter ()
#18 0x0093dd52 in api_spoolss_ClosePrinter ()
#19 0x0096f42a in process_request_pdu ()
#20 0x0096fa85 in process_complete_pdu ()
#21 0x00971ca4 in process_incoming_data ()
#22 0x00971e95 in np_write_send ()
#23 0x0073a5fa in api_fd_reply ()
#24 0x0073ac2c in handle_trans ()
#25 0x0073b8c5 in reply_trans ()
#26 0x007a2ab8 in switch_message ()
#27 0x007a6bd8 in process_smb ()
#28 0x007a6eb3 in smbd_server_connection_read_handler ()
#29 0x007a6f51 in smbd_server_connection_handler ()
#30 0x00a9fee3 in run_events_poll ()
#31 0x007a5bbb in smbd_process ()
#32 0x00d824d8 in smbd_accept_connection ()
#33 0x00a9fee3 in run_events_poll ()
#34 0x00aa0344 in s3_event_loop_once ()
#35 0x00aa079d in _tevent_loop_once ()
#36 0x00d84101 in main ()


Samba 3.6 configured with:
./configure --with-ldap --with-pam --with-pam_smbpass --enable-debug --enable-developer --enable-dmalloc --with-profiling-data --with-quotas --with-sys-quotas --with-libsmbclient --with-acl-support --with-utmp --with-winbind --localstatedir='/var/lib/samba/locks'  --prefix='/usr/local/samba' --mandir='${prefix}/man' --exec_prefix='${prefix}' --sbindir='${exec_prefix}/sbin' --bindir='${exec_prefix}/bin' --sysconfdir='/etc/samba' --with-configdir='/etc/samba' --with-lockdir='/var/lib/samba/locks' --with-logfilebase='/var/log/samba' --libdir='${exec_prefix}/lib' --with-piddir='/var/lib/samba/locks' --with-privatedir='/etc/samba/private' --with-swatdir='${prefix}/swat' --enable-cups   --with-cluster-support --with-aio-support --with-dnsupdate --with-static-modules=idmap_ldap,idmap_rid,idmap_tdb
Comment 15 Andreas Schneider 2011-10-05 09:52:21 UTC
Could someone please provide backtraces with debug symbols? Please install debug symbols for talloc and Samba packages.

Please provide version numbers of Samba and talloc. On a RPM based system.

rpm -qi libtalloc
rpm -qi samba
Comment 16 Alejandro Escanero Blanco 2011-10-05 11:56:30 UTC
My used versión is 3.6.0 from source.
With --developer I don't get any core.
Comment 17 Alejandro Escanero Blanco 2011-10-05 12:04:28 UTC
Core was generated by `/usr/local/samba/sbin/smbd'.
Program terminated with signal 6, Aborted.
#0  0x0012c402 in __kernel_vsyscall ()
(gdb) bt
#0  0x0012c402 in __kernel_vsyscall ()
#1  0x01019df0 in raise () from /lib/libc.so.6
#2  0x0101b701 in abort () from /lib/libc.so.6
#3  0x00695723 in dump_core () at lib/fault.c:391
#4  0x006a74d1 in smb_panic (why=0xc5946c "internal error") at lib/util.c:1132
#5  0x00694ec1 in fault_report (sig=11) at lib/fault.c:53
#6  0x00694ed2 in sig_fault (sig=11) at lib/fault.c:76
#7  <signal handler called>
#8  0x00745aea in dcerpc_binding_handle_call (h=0x0, object=0x0, table=0xd22440, opnum=60, r_mem=0x984e6a0, r_ptr=0xbf9a30d8) at ../librpc/rpc/binding_handle.c:524
#9  0x00569444 in dcerpc_spoolss_ReplyClosePrinter_r (h=0x0, mem_ctx=0x984e6a0, r=0xbf9a30d8) at librpc/gen_ndr/ndr_spoolss_c.c:10389
#10 0x0056981f in dcerpc_spoolss_ReplyClosePrinter (h=0x0, mem_ctx=0x984e6a0, _handle=0x98976c8, result=0xbf9a3128) at librpc/gen_ndr/ndr_spoolss_c.c:10514
#11 0x004d8677 in srv_spoolss_replycloseprinter (snum=10, prn_hnd=0x9897498) at rpc_server/spoolss/srv_spoolss_nt.c:259
#12 0x004d8a37 in printer_entry_destructor (Printer=0x9897498) at rpc_server/spoolss/srv_spoolss_nt.c:319
#13 0x00e82933 in _talloc_free_internal (ptr=0x9897498, location=0xbebb69 "rpc_server/rpc_handles.c:286") at ../talloc.c:826
#14 0x00e832f4 in _talloc_free_children_internal (tc=0x98a1cf0, ptr=0x98a1d20, location=0xbebb69 "rpc_server/rpc_handles.c:286") at ../talloc.c:1268
#15 0x00e82a70 in _talloc_free_internal (ptr=0x98a1d20, location=0xbebb69 "rpc_server/rpc_handles.c:286") at ../talloc.c:845
#16 0x00e834da in _talloc_free (ptr=0x98a1d20, location=0xbebb69 "rpc_server/rpc_handles.c:286") at ../talloc.c:1360
#17 0x00543e49 in close_policy_hnd (p=0x98849a0, hnd=0x984e780) at rpc_server/rpc_handles.c:286
#18 0x004d8d2c in close_printer_handle (p=0x98849a0, hnd=0x984e780) at rpc_server/spoolss/srv_spoolss_nt.c:370
#19 0x004dcd43 in _spoolss_ClosePrinter (p=0x98849a0, r=0x984e6d0) at rpc_server/spoolss/srv_spoolss_nt.c:1982
#20 0x004f7aee in api_spoolss_ClosePrinter (p=0x98849a0) at librpc/gen_ndr/srv_spoolss.c:2373
#21 0x0053e1be in api_rpcTNP (p=0x98849a0, pkt=0x98a1f18, api_rpc_cmds=0xd30e60, n_cmds=110) at rpc_server/srv_pipe.c:1647
#22 0x0053de05 in api_pipe_request (p=0x98849a0, pkt=0x98a1f18) at rpc_server/srv_pipe.c:1580
#23 0x0053ea78 in process_request_pdu (p=0x98849a0, pkt=0x98a1f18) at rpc_server/srv_pipe.c:1837
#24 0x0053edcc in process_complete_pdu (p=0x98849a0) at rpc_server/srv_pipe.c:1894
#25 0x0053f9f4 in process_incoming_data (p=0x98849a0, data=0x984e530 "\024", n=28) at rpc_server/srv_pipe_hnd.c:218
#26 0x0053fb0c in write_to_internal_pipe (p=0x98849a0, data=0x984e530 "\024", n=44) at rpc_server/srv_pipe_hnd.c:244
#27 0x00540469 in np_write_send (mem_ctx=0x984e4e0, ev=0x9840ed8, handle=0x98509f0, data=0x984e520 "\005", len=44) at rpc_server/srv_pipe_hnd.c:538
#28 0x00257301 in api_dcerpc_cmd (conn=0x9850a88, req=0x984e450, fsp=0x9850ea0, data=0x98a3930 "\005", length=44, max_read=1024) at smbd/ipc.c:271
#29 0x00257fe3 in api_fd_reply (conn=0x9850a88, vuid=100, req=0x984e450, setup=0x98596b0, data=0x98a3930 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:482
#30 0x002582c6 in named_pipe (conn=0x9850a88, vuid=100, req=0x984e450, name=0x98a6646 "", setup=0x98596b0, data=0x98a3930 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, msrcnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:537
#31 0x00258647 in handle_trans (conn=0x9850a88, req=0x984e450, state=0x98a3228) at smbd/ipc.c:594
#32 0x0025924b in reply_trans (req=0x984e450) at smbd/ipc.c:779
#33 0x002e021d in switch_message (type=37 '%', req=0x984e450, size=132) at smbd/process.c:1573
#34 0x002e0391 in construct_reply (sconn=0x9840f48, inbuf=0x0, size=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1609
#35 0x002e06ed in process_smb (sconn=0x9840f48, inbuf=0x984e390 "", nread=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1687
#36 0x002e1a48 in smbd_server_connection_read_handler (conn=0x9840f48, fd=11) at smbd/process.c:2307
#37 0x002e1ab8 in smbd_server_connection_handler (ev=0x9840ed8, fde=0x984e2e8, flags=1, private_data=0x9840f48) at smbd/process.c:2324
#38 0x006ba7fa in run_events_poll (ev=0x9840ed8, pollrtn=1, pfds=0x98780a8, num_pfds=2) at lib/events.c:286
#39 0x002df6d7 in smbd_server_connection_loop_once (conn=0x9840f48) at smbd/process.c:1016
#40 0x002e4584 in smbd_process (sconn=0x9840f48) at smbd/process.c:3153
#41 0x00ae6e47 in smbd_accept_connection (ev=0x9840ed8, fde=0x9863b40, flags=1, private_data=0x9862fd8) at smbd/server.c:505
#42 0x006ba7fa in run_events_poll (ev=0x9840ed8, pollrtn=1, pfds=0x985ec68, num_pfds=3) at lib/events.c:286
#43 0x006baa9e in s3_event_loop_once (ev=0x9840ed8, location=0xd12509 "smbd/server.c:838") at lib/events.c:349
#44 0x006bba5c in _tevent_loop_once (ev=0x9840ed8, location=0xd12509 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#45 0x00ae7c0b in smbd_parent_loop (parent=0x985ee88) at smbd/server.c:838
#46 0x00ae8f2c in main (argc=1, argv=0xbf9a4204) at smbd/server.c:1320
Comment 18 Andreas Schneider 2011-10-05 16:00:06 UTC
Could you please verify that smbd is using the libtalloc.so.2 library you built with the samba3 source code and it isn't using a system library which is older and doesn't contain the fix.

Check the output of

ldd /usr/local/samba/sbin/smbd

to which libtalloc library it is pointing to.
Comment 19 Alejandro Escanero Blanco 2011-10-05 16:25:46 UTC
ldd /usr/local/samba/sbin/smbd
        linux-gate.so.1 =>  (0x0012c000)
        libldap-2.3.so.0 => /usr/lib/libldap-2.3.so.0 (0x0012d000)
        liblber-2.3.so.0 => /usr/lib/liblber-2.3.so.0 (0x00167000)
        libgssapi_krb5.so.2 => /usr/lib/libgssapi_krb5.so.2 (0x00fa4000)
        libkrb5.so.3 => /usr/lib/libkrb5.so.3 (0x00b02000)
        libk5crypto.so.3 => /usr/lib/libk5crypto.so.3 (0x001b0000)
        libcom_err.so.2 => /lib/libcom_err.so.2 (0x00e16000)
        libcups.so.2 => /usr/lib/libcups.so.2 (0x00175000)
        libcrypt.so.1 => /lib/libcrypt.so.1 (0x00b98000)
        libpam.so.0 => /lib/libpam.so.0 (0x00d90000)
        libresolv.so.2 => /lib/libresolv.so.2 (0x001d6000)
        libnsl.so.1 => /lib/libnsl.so.1 (0x00ef5000)
        libdl.so.2 => /lib/libdl.so.2 (0x00c1e000)
        librt.so.1 => /lib/librt.so.1 (0x00bca000)
        libpopt.so.0 => /usr/lib/libpopt.so.0 (0x00df3000)
        libtalloc.so.2 => /usr/local/samba/lib/libtalloc.so.2 (0x001e9000)
        libtdb.so.1 => /usr/local/samba/lib/libtdb.so.1 (0x00bd3000)
        libwbclient.so.0 => /usr/local/samba/lib/libwbclient.so.0 (0x00e34000)
        libz.so.1 => /usr/lib/libz.so.1 (0x00be3000)
        libc.so.6 => /lib/libc.so.6 (0x00c22000)
        libsasl2.so.2 => /usr/lib/libsasl2.so.2 (0x00bf6000)
        libssl.so.6 => /lib/libssl.so.6 (0x00d9b000)
        libcrypto.so.6 => /lib/libcrypto.so.6 (0x00fd2000)
        libkrb5support.so.0 => /usr/lib/libkrb5support.so.0 (0x00c0f000)
        libkeyutils.so.1 => /lib/libkeyutils.so.1 (0x00f73000)
        libgnutls.so.13 => /usr/lib/libgnutls.so.13 (0x00e41000)
        libpthread.so.0 => /lib/libpthread.so.0 (0x00d68000)
        libm.so.6 => /lib/libm.so.6 (0x00ebe000)
        libaudit.so.0 => /lib/libaudit.so.0 (0x00dfb000)
        /lib/ld-linux.so.2 (0x00110000)
        libselinux.so.1 => /lib/libselinux.so.1 (0x00e19000)
        libgcrypt.so.11 => /usr/lib/libgcrypt.so.11 (0x0794b000)
        libgpg-error.so.0 => /usr/lib/libgpg-error.so.0 (0x00c18000)
        libsepol.so.1 => /lib/libsepol.so.1 (0x00f0c000)
Comment 20 Martijn Berger 2011-10-05 19:08:42 UTC
(In reply to comment #18)
> Could you please verify that smbd is using the libtalloc.so.2 library you built
> with the samba3 source code and it isn't using a system library which is older
> and doesn't contain the fix.
> 
> Check the output of
> 
> ldd /usr/local/samba/sbin/smbd
> 
> to which libtalloc library it is pointing to.

I compiled mine against 2.0.7 in the hope of solving this but that does not seem to help either. My packages are in a ppa on launchpad: https://launchpad.net/~automation/+archive/ppa

I have this problem also with a vanilla build that uses bundled libtalloc. Still I do knot know exact sequence for triggering this bug. And even with moderate use (20 so users) it happens only once in a while typicality less then once a day for me.
Comment 21 Martijn Berger 2011-10-11 09:36:48 UTC
I am not sure this is the same crash but the only thing i changed was installing libtalloc debug symbols

[Thread debugging using libthread_db enabled]
0x00007ff18cf79f7e in __libc_waitpid (pid=<value optimized out>, 
   stat_loc=0x7fffb537990c, options=<value optimized out>)
   at ../sysdeps/unix/sysv/linux/waitpid.c:32
	in ../sysdeps/unix/sysv/linux/waitpid.c
#0  0x00007ff18cf79f7e in __libc_waitpid (pid=<value optimized out>, 
   stat_loc=0x7fffb537990c, options=<value optimized out>)
   at ../sysdeps/unix/sysv/linux/waitpid.c:32
#1  0x00007ff18cf117e9 in do_system (line=<value optimized out>)
   at ../sysdeps/posix/system.c:149
#2  0x00007ff19054ec17 in smb_panic (why=<value optimized out>)
   at lib/util.c:1122
#3  0x00007ff19053fa24 in fault_report (sig=11) at lib/fault.c:53
#4  sig_fault (sig=11) at lib/fault.c:76
#5  <signal handler called>
#6  0x00007ff1902c4b80 in smb2_sendfile_send_data (state=0x7ff191aa9a80)
   at smbd/smb2_read.c:196
#7  0x00007ff18d88b4b4 in _talloc_free_internal (ptr=0x7ff191aa9a80, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:826
#8  0x00007ff18d88b233 in _talloc_free_children_internal (ptr=0x7ff191aa9300, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:1255
#9  _talloc_free_internal (ptr=0x7ff191aa9300, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:846
#10 0x00007ff18d88b233 in _talloc_free_children_internal (ptr=0x7ff191aa92a0, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:1255
#11 _talloc_free_internal (ptr=0x7ff191aa92a0, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:846
#12 0x00007ff18d88b233 in _talloc_free_children_internal (ptr=0x7ff191aa9240, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:1255
#13 _talloc_free_internal (ptr=0x7ff191aa9240, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:846
#14 0x00007ff18d88b233 in _talloc_free_children_internal (ptr=0x7ff191295da0, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:1255
#15 _talloc_free_internal (ptr=0x7ff191295da0, 
   location=0x7ff1909c8da7 "smbd/server_exit.c:160") at ../talloc.c:846
#16 0x00007ff1907c3931 in exit_server_common (how=SERVER_EXIT_NORMAL, 
   reason=0x7ff190808902 "NT_STATUS_HOST_UNREACHABLE")
   at smbd/server_exit.c:160
#17 0x00007ff1907c3b8e in exit_server_cleanly (
   explanation=0x7ff1909c8da7 "smbd/server_exit.c:160")
   at smbd/server_exit.c:205
#18 0x00007ff1902bc50b in smbd_server_connection_terminate_ex (
   sconn=<value optimized out>, 
   reason=0x7ff190808902 "NT_STATUS_HOST_UNREACHABLE", 
   location=0x7ff1907ed608 "smbd/smb2_server.c:2377")
   at smbd/smb2_server.c:613
#19 0x00007ff1902bcfe1 in smbd_smb2_request_incoming (subreq=0x7ff19190a330)
   at smbd/smb2_server.c:2377
#20 0x00007ff19056074e in tevent_req_finish (req=0x7ff191aa9a80, 
   error=<value optimized out>, location=0x0)
   at ../lib/tevent/tevent_req.c:104
#21 _tevent_req_error (req=0x7ff191aa9a80, error=<value optimized out>, 
   location=0x0) at ../lib/tevent/tevent_req.c:122
#22 0x00007ff1902b9f4a in smbd_smb2_request_read_done (subreq=0x7ff191836eb0)
   at smbd/smb2_server.c:2291
#23 0x00007ff19056074e in tevent_req_finish (req=0x7ff191aa9a80, 
   error=<value optimized out>, location=0x0)
   at ../lib/tevent/tevent_req.c:104
#24 _tevent_req_error (req=0x7ff191aa9a80, error=<value optimized out>, 
   location=0x0) at ../lib/tevent/tevent_req.c:122
#25 0x00007ff19035a854 in tstream_readv_pdu_queue_done (subreq=0x7ff191909f70)
   at ../lib/tsocket/tsocket_helpers.c:389
#26 0x00007ff19056074e in tevent_req_finish (req=0x7ff191aa9a80, 
   error=<value optimized out>, location=0x0)
   at ../lib/tevent/tevent_req.c:104
#27 _tevent_req_error (req=0x7ff191aa9a80, error=<value optimized out>, 
   location=0x0) at ../lib/tevent/tevent_req.c:122
#28 0x00007ff19035aba4 in tstream_readv_pdu_readv_done (subreq=0x7ff19190a680)
   at ../lib/tsocket/tsocket_helpers.c:280
#29 0x00007ff19056074e in tevent_req_finish (req=0x7ff191aa9a80, 
   error=<value optimized out>, location=0x0)
   at ../lib/tevent/tevent_req.c:104
#30 _tevent_req_error (req=0x7ff191aa9a80, error=<value optimized out>, 
   location=0x0) at ../lib/tevent/tevent_req.c:122
#31 0x00007ff190359c04 in tstream_readv_done (subreq=0x7ff19190a7f0)
   at ../lib/tsocket/tsocket.c:598
#32 0x00007ff19056074e in tevent_req_finish (req=0x7ff191aa9a80, 
   error=<value optimized out>, location=0x0)
   at ../lib/tevent/tevent_req.c:104
#33 _tevent_req_error (req=0x7ff191aa9a80, error=<value optimized out>, 
   location=0x0) at ../lib/tevent/tevent_req.c:122
#34 0x00007ff19035c4ba in tstream_bsd_readv_handler (
   private_data=<value optimized out>) at ../lib/tsocket/tsocket_bsd.c:1665
#35 0x00007ff19055ddc9 in run_events_poll (ev=0x7ff191295ce0, 
   pollrtn=<value optimized out>, pfds=0x7ff19175df50, num_pfds=2)
   at lib/events.c:286
#36 0x00007ff1902a867d in smbd_server_connection_loop_once (
   sconn=0x7ff191295da0) at smbd/process.c:1016
#37 smbd_process (sconn=0x7ff191295da0) at smbd/process.c:3153
#38 0x00007ff1907c1f2f in smbd_accept_connection (ev=<value optimized out>, 
   fde=<value optimized out>, flags=<value optimized out>, 
   private_data=<value optimized out>) at smbd/server.c:505
#39 0x00007ff19055ddc9 in run_events_poll (ev=0x7ff191295ce0, 
   pollrtn=<value optimized out>, pfds=0x7ff1912986b0, num_pfds=3)
   at lib/events.c:286
#40 0x00007ff19055e26f in s3_event_loop_once (ev=0x7ff191295ce0, 
   location=<value optimized out>) at lib/events.c:349
#41 0x00007ff19055e5f0 in _tevent_loop_once (ev=0x7ff191295ce0, 
   location=0x7ff1909c8474 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#42 0x00007ff1907c32f3 in smbd_parent_loop (argc=<value optimized out>, 
   argv=<value optimized out>) at smbd/server.c:838
#43 main (argc=<value optimized out>, argv=<value optimized out>)
   at smbd/server.c:1320
A debugging session is active.

	Inferior 1 [process 12150] will be detached.

Quit anyway? (y or n) [answered Y; input not from terminal]
Comment 22 Alejandro Escanero Blanco 2011-10-24 08:10:51 UTC
Same problem with Samba 3.6.1

(gdb) bt
#0  0x0012c402 in __kernel_vsyscall ()
#1  0x00f63df0 in raise () from /lib/libc.so.6
#2  0x00f65701 in abort () from /lib/libc.so.6
#3  0x0084e20f in dump_core () at lib/fault.c:391
#4  0x0085ffbd in smb_panic (why=0xe1208c "internal error") at lib/util.c:1133
#5  0x0084d9ad in fault_report (sig=11) at lib/fault.c:53
#6  0x0084d9be in sig_fault (sig=11) at lib/fault.c:76
#7  <signal handler called>
#8  0x008feaa2 in dcerpc_binding_handle_call (h=0x0, object=0x0, table=0xedb440, opnum=60, r_mem=0x8d88670, r_ptr=0xbfb82f78) at ../librpc/rpc/binding_handle.c:524
#9  0x00721eb0 in dcerpc_spoolss_ReplyClosePrinter_r (h=0x0, mem_ctx=0x8d88670, r=0xbfb82f78) at librpc/gen_ndr/ndr_spoolss_c.c:10389
#10 0x0072228b in dcerpc_spoolss_ReplyClosePrinter (h=0x0, mem_ctx=0x8d88670, _handle=0x8db8ba8, result=0xbfb82fc8) at librpc/gen_ndr/ndr_spoolss_c.c:10514
#11 0x00690c9f in srv_spoolss_replycloseprinter (snum=24, prn_hnd=0x8db8978) at rpc_server/spoolss/srv_spoolss_nt.c:259
#12 0x006a0ca2 in _spoolss_FindClosePrinterNotify (p=0x8d74200, r=0x8d886a0) at rpc_server/spoolss/srv_spoolss_nt.c:6782
#13 0x006b5284 in api_spoolss_FindClosePrinterNotify (p=0x8d74200) at librpc/gen_ndr/srv_spoolss.c:4467
#14 0x006f681e in api_rpcTNP (p=0x8d74200, pkt=0x8d7c5d8, api_rpc_cmds=0xee9e80, n_cmds=110) at rpc_server/srv_pipe.c:1647
#15 0x006f6465 in api_pipe_request (p=0x8d74200, pkt=0x8d7c5d8) at rpc_server/srv_pipe.c:1580
#16 0x006f70d8 in process_request_pdu (p=0x8d74200, pkt=0x8d7c5d8) at rpc_server/srv_pipe.c:1837
#17 0x006f742c in process_complete_pdu (p=0x8d74200) at rpc_server/srv_pipe.c:1894
#18 0x006f8054 in process_incoming_data (p=0x8d74200, data=0x8d88500 "\024", n=28) at rpc_server/srv_pipe_hnd.c:218
#19 0x006f816c in write_to_internal_pipe (p=0x8d74200, data=0x8d88500 "\024", n=44) at rpc_server/srv_pipe_hnd.c:244
#20 0x006f8ac9 in np_write_send (mem_ctx=0x8d884b0, ev=0x8d5bed8, handle=0x8d73728, data=0x8d884f0 "\005", len=44) at rpc_server/srv_pipe_hnd.c:538
#21 0x004103cd in api_dcerpc_cmd (conn=0x8d79cc0, req=0x8d88420, fsp=0x8dbb4a0, data=0x8d64c08 "\005", length=44, max_read=1024) at smbd/ipc.c:271
#22 0x004110af in api_fd_reply (conn=0x8d79cc0, vuid=100, req=0x8d88420, setup=0x8db97e0, data=0x8d64c08 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:482
#23 0x00411392 in named_pipe (conn=0x8d79cc0, vuid=100, req=0x8d88420, name=0x8d7acae "", setup=0x8db97e0, data=0x8d64c08 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, msrcnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:537
#24 0x00411713 in handle_trans (conn=0x8d79cc0, req=0x8d88420, state=0x8d74050) at smbd/ipc.c:594
#25 0x00412317 in reply_trans (req=0x8d88420) at smbd/ipc.c:779
#26 0x00498ce1 in switch_message (type=37 '%', req=0x8d88420, size=132) at smbd/process.c:1573
#27 0x00498e55 in construct_reply (sconn=0x8d5bf48, inbuf=0x0, size=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1609
#28 0x004991b1 in process_smb (sconn=0x8d5bf48, inbuf=0x8d88360 "", nread=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1687
#29 0x0049a4ff in smbd_server_connection_read_handler (conn=0x8d5bf48, fd=28) at smbd/process.c:2316
#30 0x0049a56f in smbd_server_connection_handler (ev=0x8d5bed8, fde=0x8d7c4e0, flags=1, private_data=0x8d5bf48) at smbd/process.c:2333
#31 0x00873766 in run_events_poll (ev=0x8d5bed8, pollrtn=1, pfds=0x8d7cbc0, num_pfds=2) at lib/events.c:286
#32 0x0049819b in smbd_server_connection_loop_once (conn=0x8d5bf48) at smbd/process.c:1016
#33 0x0049d006 in smbd_process (sconn=0x8d5bf48) at smbd/process.c:3157
#34 0x00c9fc93 in smbd_accept_connection (ev=0x8d5bed8, fde=0x8d91a70, flags=1, private_data=0x8d7e1d0) at smbd/server.c:505
#35 0x00873766 in run_events_poll (ev=0x8d5bed8, pollrtn=1, pfds=0x8d73320, num_pfds=3) at lib/events.c:286
#36 0x00873a0a in s3_event_loop_once (ev=0x8d5bed8, location=0xecb3c9 "smbd/server.c:838") at lib/events.c:349
#37 0x008749c8 in _tevent_loop_once (ev=0x8d5bed8, location=0xecb3c9 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#38 0x00ca0a57 in smbd_parent_loop (parent=0x8d8f758) at smbd/server.c:838
#39 0x00ca1d78 in main (argc=1, argv=0xbfb83ef4) at smbd/server.c:1320


# /usr/local/samba/sbin/smbd -V
Version 3.6.1

# ldd /usr/local/samba/sbin/smbd 
        linux-gate.so.1 =>  (0x0012c000)
        libldap-2.3.so.0 => /usr/lib/libldap-2.3.so.0 (0x0012d000)
        liblber-2.3.so.0 => /usr/lib/liblber-2.3.so.0 (0x00167000)
        libgssapi_krb5.so.2 => /usr/lib/libgssapi_krb5.so.2 (0x00175000)
        libkrb5.so.3 => /usr/lib/libkrb5.so.3 (0x001a3000)
        libk5crypto.so.3 => /usr/lib/libk5crypto.so.3 (0x00239000)
        libcom_err.so.2 => /lib/libcom_err.so.2 (0x00288000)
        libcups.so.2 => /usr/lib/libcups.so.2 (0x00f09000)
        libcrypt.so.1 => /lib/libcrypt.so.1 (0x0028b000)
        libpam.so.0 => /lib/libpam.so.0 (0x0025f000)
        libresolv.so.2 => /lib/libresolv.so.2 (0x0026a000)
        libnsl.so.1 => /lib/libnsl.so.1 (0x002bd000)
        libdl.so.2 => /lib/libdl.so.2 (0x00efc000)
        librt.so.1 => /lib/librt.so.1 (0x0027d000)
        libpopt.so.0 => /usr/lib/libpopt.so.0 (0x002d4000)
        libtalloc.so.2 => /usr/local/samba/lib/libtalloc.so.2 (0x00e87000)
        libtdb.so.1 => /usr/local/samba/lib/libtdb.so.1 (0x00e8f000)
        libwbclient.so.0 => /usr/local/samba/lib/libwbclient.so.0 (0x00ea2000)
        libz.so.1 => /usr/lib/libz.so.1 (0x00eb5000)
        libc.so.6 => /lib/libc.so.6 (0x00f41000)
        libsasl2.so.2 => /usr/lib/libsasl2.so.2 (0x00ec8000)
        libssl.so.6 => /lib/libssl.so.6 (0x0770f000)
        libcrypto.so.6 => /lib/libcrypto.so.6 (0x0617d000)
        libkrb5support.so.0 => /usr/lib/libkrb5support.so.0 (0x00ee1000)
        libkeyutils.so.1 => /lib/libkeyutils.so.1 (0x00eea000)
        libgnutls.so.13 => /usr/lib/libgnutls.so.13 (0x069f4000)
        libpthread.so.0 => /lib/libpthread.so.0 (0x06c8e000)
        libm.so.6 => /lib/libm.so.6 (0x05706000)
        libaudit.so.0 => /lib/libaudit.so.0 (0x094c9000)
        /lib/ld-linux.so.2 (0x00110000)
        libselinux.so.1 => /lib/libselinux.so.1 (0x07517000)
        libgcrypt.so.11 => /usr/lib/libgcrypt.so.11 (0x06d35000)
        libgpg-error.so.0 => /usr/lib/libgpg-error.so.0 (0x00eed000)
        libsepol.so.1 => /lib/libsepol.so.1 (0x02e6e000)

# ls -l /usr/local/samba/lib/libtalloc.so.2
lrwxrwxrwx 1 root root 18 oct 24 09:55 /usr/local/samba/lib/libtalloc.so.2 -> libtalloc.so.2.0.5
Comment 23 Jeremy Allison 2011-10-24 19:08:45 UTC
Created attachment 7026 [details]
Raw patch for 3.6.x.

Can you test this patch please to see if it fixes the problem ?

Thanks,

Jeremy.
Comment 24 Jeremy Allison 2011-10-24 21:47:52 UTC
Created attachment 7028 [details]
git-am fix that went into master
Comment 25 Alejandro Escanero Blanco 2011-10-25 16:00:49 UTC
Test with attachment 7026 [details] in samba 3.6.1:
bt
#0  0x0012c402 in __kernel_vsyscall ()
#1  0x00fc8df0 in raise () from /lib/libc.so.6
#2  0x00fca701 in abort () from /lib/libc.so.6
#3  0x006962ff in dump_core () at lib/fault.c:391
#4  0x006a80ad in smb_panic (why=0xc5a22c "internal error") at lib/util.c:1133
#5  0x00695a9d in fault_report (sig=11) at lib/fault.c:53
#6  0x00695aae in sig_fault (sig=11) at lib/fault.c:76
#7  <signal handler called>
#8  0x00746511 in dcerpc_binding_handle_call_send (mem_ctx=0x80488a8, ev=0x45c7f445, h=0xe7adec, object=0x0, table=0xd23440, opnum=60, r_mem=0x8048638, r_ptr=0xbfa7db28) at ../librpc/rpc/binding_handle.c:369
#9  0x00746c17 in dcerpc_binding_handle_call (h=0xe7adec, object=0x0, table=0xd23440, opnum=60, r_mem=0x8048638, r_ptr=0xbfa7db28) at ../librpc/rpc/binding_handle.c:534
#10 0x00569fa0 in dcerpc_spoolss_ReplyClosePrinter_r (h=0xe7adec, mem_ctx=0x8048638, r=0xbfa7db28) at librpc/gen_ndr/ndr_spoolss_c.c:10389
#11 0x0056a37b in dcerpc_spoolss_ReplyClosePrinter (h=0xe7adec, mem_ctx=0x8048638, _handle=0x804ceb0, result=0xbfa7db78) at librpc/gen_ndr/ndr_spoolss_c.c:10514
#12 0x004d8ccb in srv_spoolss_replycloseprinter (snum=23, prn_hnd=0x804cc80) at rpc_server/spoolss/srv_spoolss_nt.c:260
#13 0x004d9078 in printer_entry_destructor (Printer=0x804cc80) at rpc_server/spoolss/srv_spoolss_nt.c:319
#14 0x00e685a7 in _talloc_free_internal (ptr=0x804cc80, location=0xbec8c9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:826
#15 0x00e68f49 in _talloc_free_children_internal (tc=0x807bba8, ptr=0x807bbd8, location=0xbec8c9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:1256
#16 0x00e686f8 in _talloc_free_internal (ptr=0x807bbd8, location=0xbec8c9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:846
#17 0x00e6929e in _talloc_free (ptr=0x807bbd8, location=0xbec8c9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:1371
#18 0x00544599 in close_policy_hnd (p=0x807c898, hnd=0x8048718) at rpc_server/rpc_handles.c:286
#19 0x004d936d in close_printer_handle (p=0x807c898, hnd=0x8048718) at rpc_server/spoolss/srv_spoolss_nt.c:370
#20 0x004dd3b0 in _spoolss_ClosePrinter (p=0x807c898, r=0x8048668) at rpc_server/spoolss/srv_spoolss_nt.c:1984
#21 0x004f823e in api_spoolss_ClosePrinter (p=0x807c898) at librpc/gen_ndr/srv_spoolss.c:2373
#22 0x0053e90e in api_rpcTNP (p=0x807c898, pkt=0x80ab320, api_rpc_cmds=0xd31e80, n_cmds=110) at rpc_server/srv_pipe.c:1647
#23 0x0053e555 in api_pipe_request (p=0x807c898, pkt=0x80ab320) at rpc_server/srv_pipe.c:1580
#24 0x0053f1c8 in process_request_pdu (p=0x807c898, pkt=0x80ab320) at rpc_server/srv_pipe.c:1837
#25 0x0053f51c in process_complete_pdu (p=0x807c898) at rpc_server/srv_pipe.c:1894
#26 0x00540144 in process_incoming_data (p=0x807c898, data=0x80484c8 "\024", n=28) at rpc_server/srv_pipe_hnd.c:218
#27 0x0054025c in write_to_internal_pipe (p=0x807c898, data=0x80484c8 "\024", n=44) at rpc_server/srv_pipe_hnd.c:244
#28 0x00540bb9 in np_write_send (mem_ctx=0x8048478, ev=0x801ded8, handle=0x80791c0, data=0x80484b8 "\005", len=44) at rpc_server/srv_pipe_hnd.c:538
#29 0x002583cd in api_dcerpc_cmd (conn=0x8079220, req=0x80483e8, fsp=0x809da60, data=0x80ab3d8 "\005", length=44, max_read=1024) at smbd/ipc.c:271
#30 0x002590af in api_fd_reply (conn=0x8079220, vuid=100, req=0x80483e8, setup=0x8035b38, data=0x80ab3d8 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:482
#31 0x00259392 in named_pipe (conn=0x8079220, vuid=100, req=0x80483e8, name=0x8089286 "", setup=0x8035b38, data=0x80ab3d8 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, msrcnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:537
#32 0x00259713 in handle_trans (conn=0x8079220, req=0x80483e8, state=0x8037470) at smbd/ipc.c:594
#33 0x0025a317 in reply_trans (req=0x80483e8) at smbd/ipc.c:779
#34 0x002e0ce1 in switch_message (type=37 '%', req=0x80483e8, size=132) at smbd/process.c:1573
#35 0x002e0e55 in construct_reply (sconn=0x801df48, inbuf=0x0, size=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1609
#36 0x002e11b1 in process_smb (sconn=0x801df48, inbuf=0x8048328 "", nread=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1687
#37 0x002e24ff in smbd_server_connection_read_handler (conn=0x801df48, fd=11) at smbd/process.c:2316
#38 0x002e256f in smbd_server_connection_handler (ev=0x801ded8, fde=0x80776f8, flags=1, private_data=0x801df48) at smbd/process.c:2333
#39 0x006bb856 in run_events_poll (ev=0x801ded8, pollrtn=1, pfds=0x803a368, num_pfds=2) at lib/events.c:286
#40 0x002e019b in smbd_server_connection_loop_once (conn=0x801df48) at smbd/process.c:1016
#41 0x002e5006 in smbd_process (sconn=0x801df48) at smbd/process.c:3157
#42 0x00ae7d83 in smbd_accept_connection (ev=0x801ded8, fde=0x803e7d8, flags=1, private_data=0x8050b00) at smbd/server.c:505
#43 0x006bb856 in run_events_poll (ev=0x801ded8, pollrtn=1, pfds=0x8039dc0, num_pfds=3) at lib/events.c:286
#44 0x006bbafa in s3_event_loop_once (ev=0x801ded8, location=0xd13569 "smbd/server.c:838") at lib/events.c:349
#45 0x006bcab8 in _tevent_loop_once (ev=0x801ded8, location=0xd13569 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#46 0x00ae8b47 in smbd_parent_loop (parent=0x8039750) at smbd/server.c:838
#47 0x00ae9e68 in main (argc=1, argv=0xbfa7ec54) at smbd/server.c:1320
Comment 26 Alejandro Escanero Blanco 2011-10-25 16:05:56 UTC
Another bt about the same problem:
bt
#0  0x0012c402 in __kernel_vsyscall ()
#1  0x00fc8df0 in raise () from /lib/libc.so.6
#2  0x00fca701 in abort () from /lib/libc.so.6
#3  0x006962ff in dump_core () at lib/fault.c:391
#4  0x006a80ad in smb_panic (why=0xe6b3e4 "Bad talloc magic value - access after free") at lib/util.c:1133
#5  0x00e67643 in talloc_abort (reason=0xe6b3e4 "Bad talloc magic value - access after free") at ../lib/talloc/talloc.c:320
#6  0x00e676f1 in talloc_abort_access_after_free () at ../lib/talloc/talloc.c:336
#7  0x00e677ff in talloc_chunk_from_ptr (ptr=0x80a0e40) at ../lib/talloc/talloc.c:357
#8  0x00e691e7 in _talloc_free (ptr=0x80a0e40, location=0xbc61f8 "rpc_server/spoolss/srv_spoolss_nt.c:256") at ../lib/talloc/talloc.c:1349
#9  0x004d8c79 in srv_spoolss_replycloseprinter (snum=13, prn_hnd=0x8088260) at rpc_server/spoolss/srv_spoolss_nt.c:256
#10 0x004e8d90 in _spoolss_FindClosePrinterNotify (p=0x804c790, r=0x8048668) at rpc_server/spoolss/srv_spoolss_nt.c:6793
#11 0x004fd374 in api_spoolss_FindClosePrinterNotify (p=0x804c790) at librpc/gen_ndr/srv_spoolss.c:4467
#12 0x0053e90e in api_rpcTNP (p=0x804c790, pkt=0x8037788, api_rpc_cmds=0xd31e80, n_cmds=110) at rpc_server/srv_pipe.c:1647
#13 0x0053e555 in api_pipe_request (p=0x804c790, pkt=0x8037788) at rpc_server/srv_pipe.c:1580
#14 0x0053f1c8 in process_request_pdu (p=0x804c790, pkt=0x8037788) at rpc_server/srv_pipe.c:1837
#15 0x0053f51c in process_complete_pdu (p=0x804c790) at rpc_server/srv_pipe.c:1894
#16 0x00540144 in process_incoming_data (p=0x804c790, data=0x80484c8 "\024", n=28) at rpc_server/srv_pipe_hnd.c:218
#17 0x0054025c in write_to_internal_pipe (p=0x804c790, data=0x80484c8 "\024", n=44) at rpc_server/srv_pipe_hnd.c:244
#18 0x00540bb9 in np_write_send (mem_ctx=0x8048478, ev=0x801ded8, handle=0x804e9b8, data=0x80484b8 "\005", len=44) at rpc_server/srv_pipe_hnd.c:538
#19 0x002583cd in api_dcerpc_cmd (conn=0x804caf0, req=0x80483e8, fsp=0x80b5260, data=0x808d988 "\005", length=44, max_read=1024) at smbd/ipc.c:271
#20 0x002590af in api_fd_reply (conn=0x804caf0, vuid=100, req=0x80483e8, setup=0x80374b8, data=0x808d988 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:482
#21 0x00259392 in named_pipe (conn=0x804caf0, vuid=100, req=0x80483e8, name=0x80be1c6 "", setup=0x80374b8, data=0x808d988 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, msrcnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:537
#22 0x00259713 in handle_trans (conn=0x804caf0, req=0x80483e8, state=0x80aca08) at smbd/ipc.c:594
#23 0x0025a317 in reply_trans (req=0x80483e8) at smbd/ipc.c:779
#24 0x002e0ce1 in switch_message (type=37 '%', req=0x80483e8, size=132) at smbd/process.c:1573
#25 0x002e0e55 in construct_reply (sconn=0x801df48, inbuf=0x0, size=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1609
#26 0x002e11b1 in process_smb (sconn=0x801df48, inbuf=0x8048328 "", nread=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1687
#27 0x002e24ff in smbd_server_connection_read_handler (conn=0x801df48, fd=11) at smbd/process.c:2316
#28 0x002e256f in smbd_server_connection_handler (ev=0x801ded8, fde=0x807cf98, flags=1, private_data=0x801df48) at smbd/process.c:2333
#29 0x006bb856 in run_events_poll (ev=0x801ded8, pollrtn=1, pfds=0x803a2a8, num_pfds=2) at lib/events.c:286
#30 0x002e019b in smbd_server_connection_loop_once (conn=0x801df48) at smbd/process.c:1016
#31 0x002e5006 in smbd_process (sconn=0x801df48) at smbd/process.c:3157
#32 0x00ae7d83 in smbd_accept_connection (ev=0x801ded8, fde=0x803e7d8, flags=1, private_data=0x8050b00) at smbd/server.c:505
#33 0x006bb856 in run_events_poll (ev=0x801ded8, pollrtn=1, pfds=0x8039dc0, num_pfds=3) at lib/events.c:286
#34 0x006bbafa in s3_event_loop_once (ev=0x801ded8, location=0xd13569 "smbd/server.c:838") at lib/events.c:349
#35 0x006bcab8 in _tevent_loop_once (ev=0x801ded8, location=0xd13569 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#36 0x00ae8b47 in smbd_parent_loop (parent=0x8039750) at smbd/server.c:838
#37 0x00ae9e68 in main (argc=1, argv=0xbfa7ec54) at smbd/server.c:1320
Comment 27 Jeremy Allison 2011-10-25 16:36:25 UTC
Ah, I see the problem. Wait for a follow-up patch (I'll post shortly).
Jeremy.
Comment 28 Jeremy Allison 2011-10-25 16:46:49 UTC
Created attachment 7032 [details]
Raw patch on top of attachment 7028 [details].

Please add this on top of the previous patch. Should fix the problem correctly.

Jeremy.
Comment 29 Alejandro Escanero Blanco 2011-10-26 09:49:05 UTC
With the last patch (TWO BACKTRACES INSIDE):

 bt
#0  0x001d3402 in __kernel_vsyscall ()
#1  0x00f2edf0 in raise () from /lib/libc.so.6
#2  0x00f30701 in abort () from /lib/libc.so.6
#3  0x007fc2fb in dump_core () at lib/fault.c:391
#4  0x0080e0a9 in smb_panic (why=0xeca3e4 "Bad talloc magic value - access after free") at lib/util.c:1133
#5  0x00ec6643 in talloc_abort (reason=0xeca3e4 "Bad talloc magic value - access after free") at ../lib/talloc/talloc.c:320
#6  0x00ec66f1 in talloc_abort_access_after_free () at ../lib/talloc/talloc.c:336
#7  0x00ec67ff in talloc_chunk_from_ptr (ptr=0x94bc820) at ../lib/talloc/talloc.c:357
#8  0x00ec81e7 in _talloc_free (ptr=0x94bc820, location=0xd2c1d8 "rpc_server/spoolss/srv_spoolss_nt.c:256") at ../lib/talloc/talloc.c:1349
#9  0x0063ec79 in srv_spoolss_replycloseprinter (snum=17, prn_hnd=0x94bc1e8) at rpc_server/spoolss/srv_spoolss_nt.c:256
#10 0x0064ed8e in _spoolss_FindClosePrinterNotify (p=0x94ad2f0, r=0x9485798) at rpc_server/spoolss/srv_spoolss_nt.c:6793
#11 0x00663370 in api_spoolss_FindClosePrinterNotify (p=0x94ad2f0) at librpc/gen_ndr/srv_spoolss.c:4467
#12 0x006a490a in api_rpcTNP (p=0x94ad2f0, pkt=0x94cb570, api_rpc_cmds=0xe97e80, n_cmds=110) at rpc_server/srv_pipe.c:1647
#13 0x006a4551 in api_pipe_request (p=0x94ad2f0, pkt=0x94cb570) at rpc_server/srv_pipe.c:1580
#14 0x006a51c4 in process_request_pdu (p=0x94ad2f0, pkt=0x94cb570) at rpc_server/srv_pipe.c:1837
#15 0x006a5518 in process_complete_pdu (p=0x94ad2f0) at rpc_server/srv_pipe.c:1894
#16 0x006a6140 in process_incoming_data (p=0x94ad2f0, data=0x94855f8 "\024", n=28) at rpc_server/srv_pipe_hnd.c:218
#17 0x006a6258 in write_to_internal_pipe (p=0x94ad2f0, data=0x94855f8 "\024", n=44) at rpc_server/srv_pipe_hnd.c:244
#18 0x006a6bb5 in np_write_send (mem_ctx=0x94855a8, ev=0x9458ed8, handle=0x94be228, data=0x94855e8 "\005", len=44) at rpc_server/srv_pipe_hnd.c:538
#19 0x003be3cd in api_dcerpc_cmd (conn=0x94753f0, req=0x9485518, fsp=0x94ab670, data=0x94cb398 "\005", length=44, max_read=1024) at smbd/ipc.c:271
#20 0x003bf0af in api_fd_reply (conn=0x94753f0, vuid=100, req=0x9485518, setup=0x9477bf8, data=0x94cb398 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:482
#21 0x003bf392 in named_pipe (conn=0x94753f0, vuid=100, req=0x9485518, name=0x9478cf6 "", setup=0x9477bf8, data=0x94cb398 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, msrcnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:537
#22 0x003bf713 in handle_trans (conn=0x94753f0, req=0x9485518, state=0x946d690) at smbd/ipc.c:594
#23 0x003c0317 in reply_trans (req=0x9485518) at smbd/ipc.c:779
#24 0x00446ce1 in switch_message (type=37 '%', req=0x9485518, size=132) at smbd/process.c:1573
#25 0x00446e55 in construct_reply (sconn=0x9458f48, inbuf=0x0, size=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1609
#26 0x004471b1 in process_smb (sconn=0x9458f48, inbuf=0x9485458 "", nread=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1687
#27 0x004484ff in smbd_server_connection_read_handler (conn=0x9458f48, fd=28) at smbd/process.c:2316
#28 0x0044856f in smbd_server_connection_handler (ev=0x9458ed8, fde=0x946b548, flags=1, private_data=0x9458f48) at smbd/process.c:2333
#29 0x00821852 in run_events_poll (ev=0x9458ed8, pollrtn=1, pfds=0x945b640, num_pfds=2) at lib/events.c:286
#30 0x0044619b in smbd_server_connection_loop_once (conn=0x9458f48) at smbd/process.c:1016
#31 0x0044b006 in smbd_process (sconn=0x9458f48) at smbd/process.c:3157
#32 0x00c4dd7f in smbd_accept_connection (ev=0x9458ed8, fde=0x9474778, flags=1, private_data=0x94792c0) at smbd/server.c:505
#33 0x00821852 in run_events_poll (ev=0x9458ed8, pollrtn=1, pfds=0x948ed48, num_pfds=3) at lib/events.c:286
#34 0x00821af6 in s3_event_loop_once (ev=0x9458ed8, location=0xe79549 "smbd/server.c:838") at lib/events.c:349
#35 0x00822ab4 in _tevent_loop_once (ev=0x9458ed8, location=0xe79549 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#36 0x00c4eb43 in smbd_parent_loop (parent=0x948c038) at smbd/server.c:838
#37 0x00c4fe64 in main (argc=1, argv=0xbf98ac54) at smbd/server.c:1320

 bt
#0  0x001d3402 in __kernel_vsyscall ()
#1  0x00f2edf0 in raise () from /lib/libc.so.6
#2  0x00f30701 in abort () from /lib/libc.so.6
#3  0x007fc2fb in dump_core () at lib/fault.c:391
#4  0x0080e0a9 in smb_panic (why=0xdc020c "internal error") at lib/util.c:1133
#5  0x007fba99 in fault_report (sig=11) at lib/fault.c:53
#6  0x007fbaaa in sig_fault (sig=11) at lib/fault.c:76
#7  <signal handler called>
#8  0x008acb8e in dcerpc_binding_handle_call (h=0xb55c4ea7, object=0x0, table=0xe89440, opnum=60, r_mem=0x9485768, r_ptr=0xbf989b28) at ../librpc/rpc/binding_handle.c:524
#9  0x006cff9c in dcerpc_spoolss_ReplyClosePrinter_r (h=0xb55c4ea7, mem_ctx=0x9485768, r=0xbf989b28) at librpc/gen_ndr/ndr_spoolss_c.c:10389
#10 0x006d0377 in dcerpc_spoolss_ReplyClosePrinter (h=0xb55c4ea7, mem_ctx=0x9485768, _handle=0x94b3268, result=0xbf989b78) at librpc/gen_ndr/ndr_spoolss_c.c:10514
#11 0x0063eccb in srv_spoolss_replycloseprinter (snum=31, prn_hnd=0x94b3038) at rpc_server/spoolss/srv_spoolss_nt.c:260
#12 0x0063f078 in printer_entry_destructor (Printer=0x94b3038) at rpc_server/spoolss/srv_spoolss_nt.c:319
#13 0x00ec75a7 in _talloc_free_internal (ptr=0x94b3038, location=0xd528a9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:826
#14 0x00ec7f49 in _talloc_free_children_internal (tc=0x94a8cb0, ptr=0x94a8ce0, location=0xd528a9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:1256
#15 0x00ec76f8 in _talloc_free_internal (ptr=0x94a8ce0, location=0xd528a9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:846
#16 0x00ec829e in _talloc_free (ptr=0x94a8ce0, location=0xd528a9 "rpc_server/rpc_handles.c:286") at ../lib/talloc/talloc.c:1371
#17 0x006aa595 in close_policy_hnd (p=0x94ba4c8, hnd=0x9485848) at rpc_server/rpc_handles.c:286
#18 0x0063f36d in close_printer_handle (p=0x94ba4c8, hnd=0x9485848) at rpc_server/spoolss/srv_spoolss_nt.c:370
#19 0x006433b0 in _spoolss_ClosePrinter (p=0x94ba4c8, r=0x9485798) at rpc_server/spoolss/srv_spoolss_nt.c:1984
#20 0x0065e23a in api_spoolss_ClosePrinter (p=0x94ba4c8) at librpc/gen_ndr/srv_spoolss.c:2373
#21 0x006a490a in api_rpcTNP (p=0x94ba4c8, pkt=0x94cf8c8, api_rpc_cmds=0xe97e80, n_cmds=110) at rpc_server/srv_pipe.c:1647
#22 0x006a4551 in api_pipe_request (p=0x94ba4c8, pkt=0x94cf8c8) at rpc_server/srv_pipe.c:1580
#23 0x006a51c4 in process_request_pdu (p=0x94ba4c8, pkt=0x94cf8c8) at rpc_server/srv_pipe.c:1837
#24 0x006a5518 in process_complete_pdu (p=0x94ba4c8) at rpc_server/srv_pipe.c:1894
#25 0x006a6140 in process_incoming_data (p=0x94ba4c8, data=0x94855f8 "\024", n=28) at rpc_server/srv_pipe_hnd.c:218
#26 0x006a6258 in write_to_internal_pipe (p=0x94ba4c8, data=0x94855f8 "\024", n=44) at rpc_server/srv_pipe_hnd.c:244
#27 0x006a6bb5 in np_write_send (mem_ctx=0x94855a8, ev=0x9458ed8, handle=0x945e7f8, data=0x94855e8 "\005", len=44) at rpc_server/srv_pipe_hnd.c:538
#28 0x003be3cd in api_dcerpc_cmd (conn=0x94753f0, req=0x9485518, fsp=0x94ba5a8, data=0x94cf4d8 "\005", length=44, max_read=1024) at smbd/ipc.c:271
#29 0x003bf0af in api_fd_reply (conn=0x94753f0, vuid=100, req=0x9485518, setup=0x9460c58, data=0x94cf4d8 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:482
#30 0x003bf392 in named_pipe (conn=0x94753f0, vuid=100, req=0x9485518, name=0x94b3e36 "", setup=0x9460c58, data=0x94cf4d8 "\005", params=0x0, suwcnt=2, tdscnt=44, tpscnt=0, msrcnt=0, mdrcnt=1024, mprcnt=0) at smbd/ipc.c:537
#31 0x003bf713 in handle_trans (conn=0x94753f0, req=0x9485518, state=0x94a92f0) at smbd/ipc.c:594
#32 0x003c0317 in reply_trans (req=0x9485518) at smbd/ipc.c:779
#33 0x00446ce1 in switch_message (type=37 '%', req=0x9485518, size=132) at smbd/process.c:1573
#34 0x00446e55 in construct_reply (sconn=0x9458f48, inbuf=0x0, size=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1609
#35 0x004471b1 in process_smb (sconn=0x9458f48, inbuf=0x9485458 "", nread=132, unread_bytes=0, seqnum=0, encrypted=false, deferred_pcd=0x0) at smbd/process.c:1687
#36 0x004484ff in smbd_server_connection_read_handler (conn=0x9458f48, fd=11) at smbd/process.c:2316
#37 0x0044856f in smbd_server_connection_handler (ev=0x9458ed8, fde=0x946adb0, flags=1, private_data=0x9458f48) at smbd/process.c:2333
#38 0x00821852 in run_events_poll (ev=0x9458ed8, pollrtn=1, pfds=0x945e930, num_pfds=2) at lib/events.c:286
#39 0x0044619b in smbd_server_connection_loop_once (conn=0x9458f48) at smbd/process.c:1016
#40 0x0044b006 in smbd_process (sconn=0x9458f48) at smbd/process.c:3157
#41 0x00c4dd7f in smbd_accept_connection (ev=0x9458ed8, fde=0x9474778, flags=1, private_data=0x94792c0) at smbd/server.c:505
#42 0x00821852 in run_events_poll (ev=0x9458ed8, pollrtn=1, pfds=0x948ed48, num_pfds=3) at lib/events.c:286
#43 0x00821af6 in s3_event_loop_once (ev=0x9458ed8, location=0xe79549 "smbd/server.c:838") at lib/events.c:349
#44 0x00822ab4 in _tevent_loop_once (ev=0x9458ed8, location=0xe79549 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#45 0x00c4eb43 in smbd_parent_loop (parent=0x948c038) at smbd/server.c:838
#46 0x00c4fe64 in main (argc=1, argv=0xbf98ac54) at smbd/server.c:1320
Comment 30 Jeremy Allison 2011-10-26 16:27:08 UTC
Ok, the two things I fixed were potentially the crash bug and certainly tidy up the code, but they've obviously not addressed the root cause.

I need you to run smbd under valgrind, and reproduce the problem please. That's the only way I'm going to be able to nail this.

Jeremy.
Comment 31 Henry Wong 2011-10-26 21:59:44 UTC
Hi, 

I also have this problem. I have a Windows XP client with three Samba printers. I am using Samba 3.6.1 with your attachment 7028 [details]+7032. I can reliably reproduce this by the following:
- On XP client, Start->Printers and Faxes (Wireshark says this action sends three OpenPrinterEx requests) 
- Then close the Printers and Faxes window. The XP client sends three FCPCN requests, each causing a ReplyClosePrinter request (samba->XP) and response (XP->samba). XP client then sends ClosePrinter for each printer.
- Samba crashes while handling the ClosePrinter request and response.

I have attached a log snippet, with a few extra debug comments inserted by me into srv_spoolss_replycloseprinter(srv_spoolss_nt.c, lines 230-300). I hope they're helpful. I don't know the Samba code well enough to understand what's going on though.

Here are some things that stand out to me:

- I have three printers and three distinct prn_hnd and notify objects with the same prn_hnd->notify.cli_chan pointer. The double free seems to occur when the active_connections count drops to zero, notify.cli_chan is freed and set to NULL, yet there are other prn_hnd and prn_hnd->notify instances that point to the recently-freed cli_chan object.

- XP sends ClosePrinter requests after the {FCPCN request, ReplyClosePrinter request, ReplyClosePrinter response, FCPCN response} negotiations. From the debug messages, it looks like the FCPCN negotiations already cleaned up the cli_chan object, but receiving a ClosePrinter request calls srv_spoolss_replycloseprinter again and tries to access an already-freed cli_chan object. What's the correct behaviour here?

- It only occurs for Windows XP because it sends FCPCN before ClosePrinter. Win2k, Win7, Win2008 all just send out ClosePrinter requests without FCPCN.

- The code marked "weird if the test succeeds !!!" seems odd: How can you DLIST_REMOVE(back_channels, prn_hnd->notify.cli_chan) when prn_hnd->notify.cli_chan may be NULL? In my case, it is not NULL, but the active_connections is already zero and the cli_chan object has been freed already.


Here's a summary of the network traffic generated with an XP client:
 [...open printers and such]
 [XP->Samba]  FCPCN request for printer 1
 [XP->Samba]  FCPCN request for printer 2
 [XP->Samba]  FCPCN request for printer 3
 [Samba->XP]  ReplyClosePrinter request printer 1
 [XP->Samba]  ReplyClosePrinter response printer 1
 [Samba->XP]  FCPCN response printer 1
 [Samba->XP]  ReplyClosePrinter request printer 2
 [XP->Samba]  ReplyClosePrinter response printer 2
 [Samba->XP]  FCPCN response printer 2
 [Samba->XP]  ReplyClosePrinter request printer 3
 [XP->Samba]  ReplyClosePrinter response printer 3
   [Samba->XP]  SMB Close request (for \\XPclient\IPC$)
   [XP->Samba]  SMB Close response
   [Samba->XP]  SMB TreeDisconnect request (for \\XPclient\IPC$)
   [XP->Samba]  SMB TreeDisconnect response
 [Samba->XP]  FCPCN response printer 3
 [XP->Samba]  ClosePrinter request printer 1  -> samba crashes here
 [XP->Samba]  ClosePrinter request printer 2
 [XP->Samba]  ClosePrinter request printer 3



-------- Samba output ----------------------------------

(srv_spoolss_nt.c:244) Begin srv_spoolss_replycloseprinter(13, 0x7ffff827b630) 
(srv_spoolss_nt.c:303)   Decrementing active_connections(3->2). prn_hnd=0x7ffff827b630 notify=0x7ffff827b760 cli_chan=0x7ffff826d310 
(srv_spoolss_nt.c:307) End srv_spoolss_replycloseprinter(13, 0x7ffff827b630) 

(srv_spoolss_nt.c:244) Begin srv_spoolss_replycloseprinter(5, 0x7ffff8266bc0)
(srv_spoolss_nt.c:303)   Decrementing active_connections(2->1). prn_hnd=0x7ffff8266bc0 notify=0x7ffff8266cf0 cli_chan=0x7ffff826d310
(srv_spoolss_nt.c:307) End srv_spoolss_replycloseprinter(5, 0x7ffff8266bc0)

(srv_spoolss_nt.c:244) Begin srv_spoolss_replycloseprinter(2, 0x7ffff827ac40)
(srv_spoolss_nt.c:303)   active_connections = 1, free some stuff. prn_hnd=0x7ffff827ac40, notify=0x7ffff827ad70, cli_chan=0x7ffff826d310
(srv_spoolss_nt.c:307) End srv_spoolss_replycloseprinter(2, 0x7ffff827ac40)

(srv_spoolss_nt.c:1983) Begin _spoolss_ClosePrinter(0x7ffff8244e60, 0x7ffff826f120)
(srv_spoolss_nt.c:244)   Begin srv_spoolss_replycloseprinter(13, 0x7ffff827b630)
(srv_spoolss_nt.c:256)     Trying to close unexisting backchannel!
(srv_spoolss_nt.c:257)     weird test succeeded, prn_hnd=0x7ffff827b630 notify=0x7ffff827b760 cli_chan=0x7ffff826d310

talloc: access after free error - first free may be at rpc_server/spoolss/srv_spoolss_nt.c:284
Bad talloc magic value - access after free
smb_panic: clobber_region() last called from [get_print_db_byname(123)]
PANIC (pid 29387): Bad talloc magic value - access after free

-------- Backtrace ----------------------------------


(gdb) bt
#0  0x00007ffff42bda9e in waitpid () from /lib64/libc.so.6
#1  0x00007ffff4259861 in do_system () from /lib64/libc.so.6
#2  0x00007ffff7ab06c3 in smb_panic (why=<value optimized out>) at lib/util.c:1123
#3  0x00007ffff4bbfc40 in talloc_abort_access_after_free (ptr=0x7ffff826d310, location=0x7ffff7e27820 "rpc_server/spoolss/srv_spoolss_nt.c:259") at ../talloc.c:336
#4  talloc_chunk_from_ptr (ptr=0x7ffff826d310, location=0x7ffff7e27820 "rpc_server/spoolss/srv_spoolss_nt.c:259") at ../talloc.c:357
#5  _talloc_free (ptr=0x7ffff826d310, location=0x7ffff7e27820 "rpc_server/spoolss/srv_spoolss_nt.c:259") at ../talloc.c:1348
#6  0x00007ffff793216a in srv_spoolss_replycloseprinter (snum=13, prn_hnd=0x7ffff827b630) at rpc_server/spoolss/srv_spoolss_nt.c:259
#7  0x00007ffff793257c in printer_entry_destructor (Printer=0x7ffff827b630) at rpc_server/spoolss/srv_spoolss_nt.c:328
#8  0x00007ffff4bbf6c4 in _talloc_free_internal (ptr=0x7ffff827b630, location=0x7ffff7e4da72 "rpc_server/rpc_handles.c:286") at ../talloc.c:826
#9  0x00007ffff4bbf443 in _talloc_free_children_internal (ptr=0x7ffff826dab0, location=0x7ffff7e4da72 "rpc_server/rpc_handles.c:286") at ../talloc.c:1255
#10 _talloc_free_internal (ptr=0x7ffff826dab0, location=0x7ffff7e4da72 "rpc_server/rpc_handles.c:286") at ../talloc.c:846
#11 0x00007ffff797d94c in close_policy_hnd (p=0x7ffff8244e60, hnd=<value optimized out>) at rpc_server/rpc_handles.c:286
#12 0x00007ffff7931857 in close_printer_handle (p=0x7ffff8244e60, hnd=0x7ffff826f240) at rpc_server/spoolss/srv_spoolss_nt.c:379
#13 0x00007ffff7936f30 in _spoolss_ClosePrinter (p=0x7ffff8244e60, r=0x7ffff826f120) at rpc_server/spoolss/srv_spoolss_nt.c:1994
#14 0x00007ffff7949d1f in api_spoolss_ClosePrinter (p=0x7ffff8244e60) at librpc/gen_ndr/srv_spoolss.c:2373
#15 0x00007ffff7978387 in api_rpcTNP (p=0x7ffff8244e60, pkt=0x7ffff827ea20, api_rpc_cmds=0x7ffff8238480, n_cmds=110) at rpc_server/srv_pipe.c:1647
#16 0x00007ffff7978aca in api_pipe_request (p=0x7ffff8244e60, pkt=0x7ffff827ea20) at rpc_server/srv_pipe.c:1580
#17 process_request_pdu (p=0x7ffff8244e60, pkt=0x7ffff827ea20) at rpc_server/srv_pipe.c:1837
#18 0x00007ffff7978d72 in process_complete_pdu (p=0x7ffff8244e60) at rpc_server/srv_pipe.c:1894
#19 0x00007ffff797adbf in process_incoming_data (p=0x7ffff8244e60, data=0x7ffff826ee80 "\024", n=28) at rpc_server/srv_pipe_hnd.c:218
#20 0x00007ffff797afc8 in write_to_internal_pipe (mem_ctx=<value optimized out>, ev=0x7ffff82404f0, handle=<value optimized out>, data=<value optimized out>, len=28)
    at rpc_server/srv_pipe_hnd.c:244
#21 np_write_send (mem_ctx=<value optimized out>, ev=0x7ffff82404f0, handle=<value optimized out>, data=<value optimized out>, len=28) at rpc_server/srv_pipe_hnd.c:538
#22 0x00007ffff775e30c in api_dcerpc_cmd (conn=0x7ffff82606d0, vuid=<value optimized out>, req=<value optimized out>, setup=<value optimized out>, data=0x7ffff82b8ea0 "\005", 
    params=<value optimized out>, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=<value optimized out>, mprcnt=0) at smbd/ipc.c:271
#23 api_fd_reply (conn=0x7ffff82606d0, vuid=<value optimized out>, req=<value optimized out>, setup=<value optimized out>, data=0x7ffff82b8ea0 "\005", 
    params=<value optimized out>, suwcnt=2, tdscnt=44, tpscnt=0, mdrcnt=<value optimized out>, mprcnt=0) at smbd/ipc.c:482
#24 0x00007ffff775e8b2 in named_pipe (conn=0x7ffff82606d0, req=0x7ffff826ed10, state=0x7ffff825def0) at smbd/ipc.c:537
#25 handle_trans (conn=0x7ffff82606d0, req=0x7ffff826ed10, state=0x7ffff825def0) at smbd/ipc.c:594
#26 0x00007ffff775f60d in reply_trans (req=0x7ffff826ed10) at smbd/ipc.c:779
#27 0x00007ffff77c4e43 in switch_message (type=<value optimized out>, req=0x7ffff826ed10, size=<value optimized out>) at smbd/process.c:1573
#28 0x00007ffff77c8838 in construct_reply (sconn=0x7ffff82405b0, inbuf=<value optimized out>, nread=<value optimized out>, unread_bytes=0, seqnum=<value optimized out>, 
    encrypted=<value optimized out>, deferred_pcd=0x0) at smbd/process.c:1609
#29 process_smb (sconn=0x7ffff82405b0, inbuf=<value optimized out>, nread=<value optimized out>, unread_bytes=0, seqnum=<value optimized out>, encrypted=<value optimized out>, 
    deferred_pcd=0x0) at smbd/process.c:1687
#30 0x00007ffff77c98f4 in smbd_server_connection_read_handler (conn=0x7ffff82405b0, fd=<value optimized out>) at smbd/process.c:2316
#31 0x00007ffff77c995f in smbd_server_connection_handler (ev=<value optimized out>, fde=<value optimized out>, flags=<value optimized out>, private_data=<value optimized out>)
    at smbd/process.c:2333
#32 0x00007ffff7ac12ff in run_events_poll (ev=0x7ffff82404f0, pollrtn=<value optimized out>, pfds=0x7ffff824d3e0, num_pfds=7) at lib/events.c:286
#33 0x00007ffff77c8589 in smbd_server_connection_loop_once (sconn=0x7ffff82405b0) at smbd/process.c:1016
#34 smbd_process (sconn=0x7ffff82405b0) at smbd/process.c:3157
#35 0x00007ffff7d4a42b in smbd_accept_connection (ev=<value optimized out>, fde=<value optimized out>, flags=<value optimized out>, private_data=<value optimized out>)
    at smbd/server.c:429
#36 0x00007ffff7ac12ff in run_events_poll (ev=0x7ffff82404f0, pollrtn=<value optimized out>, pfds=0x7ffff8263840, num_pfds=6) at lib/events.c:286
#37 0x00007ffff7ac1760 in s3_event_loop_once (ev=0x7ffff82404f0, location=<value optimized out>) at lib/events.c:349
#38 0x00007ffff7ac1ceb in _tevent_loop_once (ev=0x7ffff82404f0, location=0x7ffff7f5a447 "smbd/server.c:838") at ../lib/tevent/tevent.c:494
#39 0x00007ffff7d4c236 in smbd_parent_loop (argc=<value optimized out>, argv=<value optimized out>) at smbd/server.c:838
#40 main (argc=<value optimized out>, argv=<value optimized out>) at smbd/server.c:1320
Comment 32 Alejandro Escanero Blanco 2011-10-27 17:43:51 UTC
I get this error when try to use valgrind:
valgrind: mmap(0x108000, 12128256) failed in UME with error 22 (Invalid argument).
valgrind: this can be caused by executables with very large text, data or bss segments.


There are any manner to use valgrind to debug samba in RHEL 5.5?
Comment 33 Henry Wong 2011-10-29 16:37:46 UTC
Created attachment 7045 [details]
Fix double-free caused by calling srv_spoolss_replycloseprinter twice.

It looks to me like there is a double free on the notify->cli_chan object:
- srv_spoolss_replyopenprinter and srv_spoolss_replycloseprinter should be paired (it adds and removes a reference to a back_channel).
- srv_spoolss_replyopenprinter is called in response to FindFirstPrinterChangeNotifyEx.
- srv_spoolss_replycloseprinter is called in response to FindClosePrinterNotify and in printer_entry_destructor.

The patch sets the printer->notify.cli_chan pointer to NULL once that printer's connection is removed, to make srv_spoolss_replycloseprinter paired with srv_spoolss_replyopenprinter.
Comment 34 Henry Wong 2011-10-29 16:44:12 UTC
For me, the crash is caused by Windows XP sending a FindClosePrinterNotify followed by ClosePrinter, so srv_spoolss_replycloseprinter happens twice for every srv_spoolss_replyopenprinter -> Double free.


Some other things:

There are many instances in srv_spoolss_nt.c where (cli_chan->active_connections > 0) is tested, but that test should never be false. The cli_chan object is freed whenever active_connections should be 0, so that test can be false only if the test itself is accessing an already-freed object. I think it might be a good idea to remove them and rely solely on (cli_chan != NULL).

I also wonder what happens if a client sends multiple FindFirstPrinterChangeNotifyEx calls. It seems like it would continually add references to a back_channel that would never be cleaned up, even after the printer is closed?
Comment 35 Henry Wong 2011-11-03 14:15:52 UTC
Alejandro, Martijn,

Does my patch (attachment 7045 [details]) fix the crashes you are seeing?
Comment 36 Martijn Berger 2011-11-03 14:24:35 UTC
(In reply to comment #35)
> Alejandro, Martijn,
> 
> Does my patch (attachment 7045 [details]) fix the crashes you are seeing?

Do I apply only the one patch or all of them ?

Martijn
Comment 37 Henry Wong 2011-11-03 15:31:01 UTC
(In reply to comment #36)

My (one-line) patch is independent of Jeremy's, so it's up to you whether to also apply Jeremy's fixes.
Comment 38 Alejandro Escanero Blanco 2011-11-04 09:55:34 UTC
Tested about two hours in production state: All ok, no cores.
Comment 39 Jeremy Allison 2011-11-04 18:13:34 UTC
Henry - really good catch ! Pointer ref counting can be tricky :-(.

I'll apply your fix to master and get it into 3.6.next.

For master I'll also do the tidyup you suggested.

Jeremy.
Comment 40 Henry Wong 2011-11-04 18:19:29 UTC
(In reply to comment #39)
> Henry - really good catch ! Pointer ref counting can be tricky :-(.
> 
> I'll apply your fix to master and get it into 3.6.next.
> 
> For master I'll also do the tidyup you suggested.
> 
> Jeremy.

Great, thanks!
Comment 41 Jeremy Allison 2011-11-04 21:41:34 UTC
Created attachment 7062 [details]
git-am fix for 3.6.next.

Guenther please review for 3.6.x.

I'm making this a blocker as it causes WindowsXP print clients to crash smbd.

Jeremy.
Comment 42 Jeremy Allison 2011-11-04 21:41:59 UTC
Making a blocker as this really must get reviewed and added for 3.6.next.

Jeremy.
Comment 43 Jeremy Allison 2011-11-04 21:42:18 UTC
Comment on attachment 7062 [details]
git-am fix for 3.6.next.

Adding metze to get faster coverage.
Comment 44 Stefan Metzmacher 2011-11-05 08:32:45 UTC
Comment on attachment 7062 [details]
git-am fix for 3.6.next.

Shouldn't we only set it to NULL if active_connections reaches 0?
Comment 45 Stefan Metzmacher 2011-11-05 08:57:18 UTC
Comment on attachment 7062 [details]
git-am fix for 3.6.next.

Ok, got it... Looks good
Comment 46 Stefan Metzmacher 2011-11-05 08:58:02 UTC
Karolin, please pick for the next release
Comment 47 Karolin Seeger 2011-11-09 18:44:22 UTC
(In reply to comment #45)
> Comment on attachment 7062 [details]
> git-am fix for 3.6.next.
> 
> Ok, got it... Looks good

Pushed to v3-6-test.
Closing out bug report.

Thanks!