Bug 9853 - smbd crash: assert failed at open.c (1527): ret
smbd crash: assert failed at open.c (1527): ret
Status: RESOLVED FIXED
Product: Samba 4.0
Classification: Unclassified
Component: File services
4.0.5
All All
: P5 major
: ---
Assigned To: Samba QA Contact
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2013-05-05 20:22 UTC by Nick Semenkovich
Modified: 2014-10-02 14:41 UTC (History)
1 user (show)

See Also:


Attachments
gdb; bt full (37.82 KB, text/plain)
2013-05-05 20:24 UTC, Nick Semenkovich
no flags Details
gdb; bt full (#2) (37.85 KB, text/plain)
2013-05-14 04:52 UTC, Nick Semenkovich
no flags Details
gdb; bt full (from 4.1.0pre1-GIT-1c9ef67) (37.96 KB, text/plain)
2013-05-25 19:49 UTC, Nick Semenkovich
no flags Details
crash from user, "coco" (70.46 KB, text/plain)
2013-07-02 20:38 UTC, Nick Semenkovich
no flags Details
level8_log.%U (1k lines) (3.85 KB, text/plain)
2013-07-02 20:39 UTC, Nick Semenkovich
no flags Details
level8_log. (1k lines) (49.71 KB, text/plain)
2013-07-02 20:39 UTC, Nick Semenkovich
no flags Details
smb.conf (1.12 KB, text/plain)
2013-07-02 20:40 UTC, Nick Semenkovich
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Nick Semenkovich 2013-05-05 20:22:11 UTC
I'm intermittently getting this crash in samba4. Haven't found a reliable repro yet.

Compiled from:

commit 5f82641553e33bc236b6c8a4f5cfc1cf3b722eea
Author: Volker Lendecke <vl@samba.org>
Date:   Thu Apr 25 14:24:08 2013 +0200

    libsmb: Use sizeof instead of explicit numbers




In the samba logs, I see a lot of:

[2013/05/05 07:40:36,  0] ../source4/rpc_server/drsuapi/writespn.c:237(dcesrv_drsuapi_DsWriteAccountSpn)
  Failed to modify SPNs on CN=AIO6,CN=Computers,DC=corp,DC=example,DC=com: error in module acl: insufficient access rights (50)
[2013/05/05 07:40:36,  0] ../source4/rpc_server/drsuapi/writespn.c:237(dcesrv_drsuapi_DsWriteAccountSpn)
  Failed to modify SPNs on CN=AIO6,CN=Computers,DC=corp,DC=example,DC=com: error in module acl: insufficient access rights (50)




The smbd crash:

  Oplock break failed for file cook/AppData/Roaming/Microsoft/Windows/Libraries/Documents.library-ms -- replying anyway
[2013/05/05 14:59:49.503775,  0] ../source3/smbd/oplock.c:333(oplock_timeout_handler)
  Oplock break failed for file cook/AppData/Roaming/Microsoft/Windows/Libraries/Pictures.library-ms -- replying anyway
[2013/05/05 14:59:49.504284,  0] ../source3/smbd/open.c:1527(defer_open_done)
  PANIC: assert failed at ../source3/smbd/open.c(1527): ret
[2013/05/05 14:59:49.504470,  0] ../source3/lib/util.c:810(smb_panic_s3)
  PANIC (pid 7579): assert failed: ret
[2013/05/05 14:59:49.527566,  0] ../source3/lib/util.c:921(log_stack_trace)
  BACKTRACE: 25 stack frames:
   #0 /usr/local/samba/lib/libsmbconf.so.0(log_stack_trace+0x1f) [0x7f0f4d590cda]
   #1 /usr/local/samba/lib/libsmbconf.so.0(smb_panic_s3+0x6c) [0x7f0f4d590b2d]
   #2 /usr/local/samba/lib/libsamba-util.so.0(smb_panic+0x28) [0x7f0f4f014c39]
   #3 /usr/local/samba/lib/private/libsmbd_base.so(+0x1397b2) [0x7f0f4eb837b2]
   #4 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7f0f4e83ea13]
   #5 /usr/local/samba/lib/private/libtevent.so.0(+0x5a45) [0x7f0f4e83ea45]
   #6 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_done+0x25) [0x7f0f4e83ea6c]
   #7 /usr/local/samba/lib/libsmbconf.so.0(+0x35ef3) [0x7f0f4d5a2ef3]
   #8 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7f0f4e83ea13]
   #9 /usr/local/samba/lib/private/libtevent.so.0(+0x5a45) [0x7f0f4e83ea45]
   #10 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_done+0x25) [0x7f0f4e83ea6c]
   #11 /usr/local/samba/lib/libsmbconf.so.0(+0x31436) [0x7f0f4d59e436]
   #12 /usr/local/samba/lib/private/libtevent.so.0(tevent_common_loop_immediate+0x1f5) [0x7f0f4e83df78]
   #13 /usr/local/samba/lib/libsmbconf.so.0(run_events_poll+0x56) [0x7f0f4d5b1de3]
   #14 /usr/local/samba/lib/libsmbconf.so.0(+0x454a7) [0x7f0f4d5b24a7]
   #15 /usr/local/samba/lib/private/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f0f4e83d0b2]
   #16 /usr/local/samba/lib/private/libsmbd_base.so(smbd_process+0x12ef) [0x7f0f4ebb2454]
   #17 /usr/local/samba/sbin/smbd() [0x409ec6]
   #18 /usr/local/samba/lib/libsmbconf.so.0(run_events_poll+0x55f) [0x7f0f4d5b22ec]
   #19 /usr/local/samba/lib/libsmbconf.so.0(+0x455b8) [0x7f0f4d5b25b8]
   #20 /usr/local/samba/lib/private/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f0f4e83d0b2]
   #21 /usr/local/samba/sbin/smbd() [0x40ab30]
   #22 /usr/local/samba/sbin/smbd(main+0x1709) [0x40c38a]
   #23 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f0f4bdffea5]
   #24 /usr/local/samba/sbin/smbd() [0x4055e9]
[2013/05/05 14:59:49.528469,  0] ../source3/lib/util.c:822(smb_panic_s3)
  smb_panic(): calling panic action [/bin/sleep 99999999]
Comment 1 Nick Semenkovich 2013-05-05 20:24:15 UTC
Created attachment 8849 [details]
gdb; bt full
Comment 2 Volker Lendecke 2013-05-06 12:48:26 UTC
Any chance we can get a debug level 10 log of this? One way that I can imagine this happening is some wrong talloc hierarchy or a missing explicit free of the wait event.
Comment 3 Nick Semenkovich 2013-05-06 22:38:22 UTC
(In reply to comment #2)
> Any chance we can get a debug level 10 log of this? One way that I can imagine
> this happening is some wrong talloc hierarchy or a missing explicit free of the
> wait event.

Hm, maybe if I end up with a repro. This crash seems intermittent & semi-rare, and I'm not sure I want to constantly run smbd in debug level 10 ...
Comment 4 Nick Semenkovich 2013-05-14 04:51:24 UTC
Crash just happened again when logging in simultaneously on two machines as the domain administrator.

Using 4.1.0pre1-GIT-392b01f.

Will attach another backtrace, trying to make more of a repro.
Comment 5 Nick Semenkovich 2013-05-14 04:52:37 UTC
Created attachment 8883 [details]
gdb; bt full (#2)
Comment 6 Nick Semenkovich 2013-05-25 19:48:53 UTC
Still seeing this as of 4.1.0pre1-GIT-1c9ef67

commit 1c9ef675d1a44fb9b0d599f96391abf1e21981c1
Author: Volker Lendecke <vl@samba.org>
Date:   Fri May 17 15:14:58 2013 +0200

    smbd: Fix a ISO C90 forbids mixed declarations and code warning

    Signed-off-by: Volker Lendecke <vl@samba.org>
    Reviewed-by: Matthieu Patou <mat@matws.net>

    Autobuild-User(master): Matthieu Patou <mat@samba.org>
    Autobuild-Date(master): Sat May 18 01:40:04 CEST 2013 on sn-devel-104


FWIW, this user also triggered bug 9903.


Another smbd.log:

[2013/05/25 14:40:08.338658,  0] ../source3/smbd/oplock.c:333(oplock_timeout_handler)
  Oplock break failed for file betsy/Searches/desktop.ini -- replying anyway
[2013/05/25 14:40:08.339238,  0] ../source3/smbd/open.c:1527(defer_open_done)
  PANIC: assert failed at ../source3/smbd/open.c(1527): ret
[2013/05/25 14:40:08.339399,  0] ../source3/lib/util.c:810(smb_panic_s3)
  PANIC (pid 15161): assert failed: ret
[2013/05/25 14:40:08.340271,  0] ../source3/lib/util.c:921(log_stack_trace)
  BACKTRACE: 25 stack frames:
   #0 /usr/local/samba/lib/libsmbconf.so.0(log_stack_trace+0x1f) [0x7f9ca4103caa]
   #1 /usr/local/samba/lib/libsmbconf.so.0(smb_panic_s3+0x6c) [0x7f9ca4103afd]
   #2 /usr/local/samba/lib/libsamba-util.so.0(smb_panic+0x28) [0x7f9ca5b87c49]
   #3 /usr/local/samba/lib/private/libsmbd_base.so(+0x1397ae) [0x7f9ca56f67ae]
   #4 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7f9ca53b1a13]
   #5 /usr/local/samba/lib/private/libtevent.so.0(+0x5a45) [0x7f9ca53b1a45]
   #6 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_done+0x25) [0x7f9ca53b1a6c]
   #7 /usr/local/samba/lib/libsmbconf.so.0(+0x35ef3) [0x7f9ca4115ef3]
   #8 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7f9ca53b1a13]
   #9 /usr/local/samba/lib/private/libtevent.so.0(+0x5a45) [0x7f9ca53b1a45]
   #10 /usr/local/samba/lib/private/libtevent.so.0(_tevent_req_done+0x25) [0x7f9ca53b1a6c]
   #11 /usr/local/samba/lib/libsmbconf.so.0(+0x31436) [0x7f9ca4111436]
   #12 /usr/local/samba/lib/private/libtevent.so.0(tevent_common_loop_immediate+0x1f5) [0x7f9ca53b0f78]
   #13 /usr/local/samba/lib/libsmbconf.so.0(run_events_poll+0x56) [0x7f9ca4124de3]
   #14 /usr/local/samba/lib/libsmbconf.so.0(+0x454a7) [0x7f9ca41254a7]
   #15 /usr/local/samba/lib/private/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f9ca53b00b2]
   #16 /usr/local/samba/lib/private/libsmbd_base.so(smbd_process+0x12ef) [0x7f9ca5725449]
   #17 /usr/local/samba/sbin/smbd() [0x409ec6]
   #18 /usr/local/samba/lib/libsmbconf.so.0(run_events_poll+0x55f) [0x7f9ca41252ec]
   #19 /usr/local/samba/lib/libsmbconf.so.0(+0x455b8) [0x7f9ca41255b8]
   #20 /usr/local/samba/lib/private/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f9ca53b00b2]
   #21 /usr/local/samba/sbin/smbd() [0x40ab30]
   #22 /usr/local/samba/sbin/smbd(main+0x1709) [0x40c38a]
   #23 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f9ca2972ea5]
   #24 /usr/local/samba/sbin/smbd() [0x4055e9]
[2013/05/25 14:40:08.341474,  0] ../source3/lib/util.c:822(smb_panic_s3)
  smb_panic(): calling panic action [/bin/sleep 99999999]
Terminated
[2013/05/25 14:46:30.461501,  0] ../source3/lib/util.c:830(smb_panic_s3)
  smb_panic(): action returned status 143
[2013/05/25 14:46:30.461743,  0] ../source3/lib/dumpcore.c:317(dump_core)
  dumping core in /usr/local/samba/var/cores/smbd
[2013/05/25 14:46:30.541106,  1] ../source3/smbd/server.c:456(remove_child_pid)
  Scheduled cleanup of brl and lock database after unclean shutdown
Comment 7 Nick Semenkovich 2013-05-25 19:49:39 UTC
Created attachment 8922 [details]
gdb; bt full (from 4.1.0pre1-GIT-1c9ef67)
Comment 8 Nick Semenkovich 2013-05-28 15:35:37 UTC
(In reply to comment #2)
> Any chance we can get a debug level 10 log of this? One way that I can imagine
> this happening is some wrong talloc hierarchy or a missing explicit free of the
> wait event.

If I set "log level = 10" under [global] in smb.conf, will that force both samba & smbd into level 10 logging?
Comment 9 Volker Lendecke 2013-05-29 06:41:07 UTC
It should, yes
Comment 10 Nick Semenkovich 2013-06-18 19:52:00 UTC
(In reply to comment #9)
> It should, yes

Still happening as of the recent commit:

commit 9f25ad44a93da09b3a7c14a4a1a0e78c5a1b529c
Author: Volker Lendecke <vl@samba.org>
Date:   Thu Jun 6 11:37:59 2013 +0200

    librpc: Shorten dcerpc_binding_handle_call a bit



It's tough to get a level 10 debug log, since that seems to really slow down the machine (and the crash happens very intermittently -- every 3-5 days with 15-20 users on Win8 Pro).

(Is there any alternative to level 10 debug logs? I'm trying a ramdisk now, but it'd be great if there were some buffer that just dumped recent level 10 logs on a crash.)
Comment 11 Nick Semenkovich 2013-07-02 20:37:36 UTC
Attaching a level 8 log now. This might be related to bug 9842 -- I see that crash (around "krb5_cc_store_cred") after this open.c:1527 crash.


Built with commit:

commit af41eb6bd4889a7cd0c7a0bd1553e3534f8f06ad
Author: Aurélien Aptel <aurelien.aptel@gmail.com>
Date:   Fri Jun 28 17:34:26 2013 +0200

    docs-xml/manpages/smbclient.1.xml: fix case of -T flag in example.

    Signed-off-by: Aurélien Aptel <aurelien.aptel@gmail.com>
    Reviewed-by: David Disseldorp <ddiss@samba.org>

    Autobuild-User(master): David Disseldorp <ddiss@samba.org>
    Autobuild-Date(master): Fri Jun 28 17:45:31 CEST 2013 on sn-devel-1
Comment 12 Nick Semenkovich 2013-07-02 20:38:12 UTC
Created attachment 9016 [details]
crash from user, "coco"
Comment 13 Nick Semenkovich 2013-07-02 20:39:12 UTC
Created attachment 9017 [details]
level8_log.%U (1k lines)
Comment 14 Nick Semenkovich 2013-07-02 20:39:25 UTC
Created attachment 9018 [details]
level8_log. (1k lines)
Comment 15 Nick Semenkovich 2013-07-02 20:40:53 UTC
Created attachment 9019 [details]
smb.conf
Comment 16 Nick Semenkovich 2013-07-08 19:28:33 UTC
Another crash, with more organized crash logs (level9+) and GDB at:
http://remote.aldinetravel.com/samba-crash/


There are consistently /two/ crashes, one always following the other:

$ grep panic *
log.coco.txt:[2013/07/08 08:30:52.766641,  0] ../source3/lib/util.c:822(smb_panic_s3)
log.coco.txt:  smb_panic(): calling panic action [/home/semenko/panic-action 17188]
log.%U.txt:[2013/07/08 08:31:27,  0] ../lib/util/fault.c:133(smb_panic_default)
log.%U.txt:  smb_panic(): calling panic action [/home/semenko/panic-action 3012]


Please let me know if there's any other info I can provide.
Comment 17 Nick Semenkovich 2013-07-24 22:02:34 UTC
This is still crashing (though the winbind fixes mean it no longer causes a second panic), and I have some additional level 9 logs.

Is there a way to run samba with only the SMBD service logging at level 10? (e.g. can I add some service-specific log setting to smb.conf?).




[2013/07/19 13:21:06.127147,  5] ../lib/dbwrap/dbwrap.c:187(dbwrap_check_lock_order)
  check lock order 3 for /usr/local/samba/var/lock/dbwrap_watchers.tdb
[2013/07/19 13:21:06.127229,  5] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor)
  release lock order 3 for /usr/local/samba/var/lock/dbwrap_watchers.tdb
[2013/07/19 13:21:06.127260,  5] ../source3/lib/messages.c:340(messaging_deregister)
  Deregistering messaging pointer for type 4003 - private_data=0x7f24cc06d890
[2013/07/19 13:21:06.127290,  0] ../source3/smbd/open.c:1527(defer_open_done)
  PANIC: assert failed at ../source3/smbd/open.c(1527): ret
[2013/07/19 13:21:06.127395,  0] ../source3/lib/util.c:810(smb_panic_s3)
  PANIC (pid 28451): assert failed: ret
[2013/07/19 13:21:06.128151,  0] ../source3/lib/util.c:921(log_stack_trace)
  BACKTRACE: 25 stack frames:
<SNIP>
Comment 18 Nick Semenkovich 2014-10-02 14:41:03 UTC
This seems to have resolved itself (haven't seen it in a ~year). Closing.