Created attachment 13252 [details] Full logs On connection force close file_close_conn(conn) calls close_file(req=NULL, fsp, SHUTDOWN_CLOSE) for all open files. close_file() eventually calls file_free() that frees fsp. But in this flow in file_free() req is NULL, so remove_smb2_chained_fsp() is not called. If there was async notify request, it still holds a pointer to already deleted fsp so smbd can panic with segmentation fault. The panic is easily reproducible, if enable talloc_fill. In the log below you can see that fsp 0x7f38ed3ba6f0 is accessed after is already was freed: [2017/06/05 16:22:32.347021, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 8 [2017/06/05 16:22:32.349155, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:65(fsp_new) fsp_new: fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:32.351464, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:130(file_new) allocated file structure fnum 111888149 (2 used) [2017/06/05 16:22:32.357834, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1397(smbd_smb2_create_send) smbd_smb2_create_send: . - fnum 111888149 [2017/06/05 16:22:32.358315, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_NOTIFY] mid = 9 [2017/06/05 16:22:32.358390, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:32.358577, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_notify.c:232(smbd_smb2_notify_send) smbd_smb2_notify_send: . - fnum 111888149 [2017/06/05 16:22:32.364550, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1571(smbd_smb2_request_pending_timer) smbd_smb2_request_pending_queue: opcode[SMB2_OP_NOTIFY] mid 9 going async [2017/06/05 16:22:42.005483, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/conn_idle.c:120(conn_force_tdis) conn_force_tdis: Forcing close of share 'vol1' (wire_id=0xe394d695) [2017/06/05 16:22:42.011140, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:513(fsp_free) fsp_free(fsp=0x7f38ed3ba6f0) [2017/06/05 16:22:42.011626, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:570(file_free) freed files structure 111888149 (0 used) [2017/06/05 16:22:42.018911, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_notify.c:118(smbd_smb2_request_notify_done) smbd_smb2_request_notify_done: req->compat_chain_fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:42.019636, 3, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3132(smbd_smb2_request_error_ex) smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[STATUS_NOTIFY_CLEANUP] || at ../source3/smbd/smb2_notify.c:125 [2017/06/05 16:22:42.019732, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[STATUS_NOTIFY_CLEANUP] body[8] dyn[yes:1] at ../source3/smbd/smb2_server.c:3189 [2017/06/05 16:22:42.019811, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2717(smbd_smb2_request_reply_update_counts) smbd_smb2_request_reply_update_counts: compat_chain_fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:42.020173, 0, pid=2877, effective(0, 0), real(0, 0)] ../lib/util/fault.c:78(fault_report) =============================================================== [2017/06/05 16:22:42.020853, 0, pid=2877, effective(0, 0), real(0, 0)] ../lib/util/fault.c:79(fault_report) INTERNAL ERROR: Signal 11 in pid 2877 (4.5.10) Please read the Trouble-Shooting section of the Samba HOWTO [2017/06/05 16:22:42.021481, 0, pid=2877, effective(0, 0), real(0, 0)] ../lib/util/fault.c:81(fault_report) =============================================================== [2017/06/05 16:22:42.021992, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/util.c:791(smb_panic_s3) PANIC (pid 2877): internal error [2017/06/05 16:22:42.023094, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/util.c:910(log_stack_trace) BACKTRACE: 34 stack frames: #0 /usr/lib/libsmbconf.so.0(log_stack_trace+0x1f) [0x7f38e855f4b9] #1 /usr/lib/libsmbconf.so.0(smb_panic_s3+0x70) [0x7f38e855f2ef] #2 /usr/lib/libsamba-util.so.0(smb_panic+0x28) [0x7f38eb04814d] #3 /usr/lib/libsamba-util.so.0(+0x21e25) [0x7f38eb047e25] #4 /usr/lib/libsamba-util.so.0(+0x21e3a) [0x7f38eb047e3a] #5 /lib/x86_64-linux-gnu/libpthread.so.0(+0x10330) [0x7f38eb2b4330] #6 /usr/lib/samba/libsmbd-base-samba4.so(+0x1a6bf1) [0x7f38eabb7bf1] #7 /usr/lib/samba/libsmbd-base-samba4.so(+0x1a6e50) [0x7f38eabb7e50] #8 /usr/lib/samba/libsmbd-base-samba4.so(smbd_smb2_request_done_ex+0x622) [0x7f38eabb9638] #9 /usr/lib/samba/libsmbd-base-samba4.so(smbd_smb2_request_error_ex+0x2f4) [0x7f38eabb993a] #10 /usr/lib/samba/libsmbd-base-samba4.so(+0x1c9205) [0x7f38eabda205] #11 /usr/lib/samba/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7f38e9ff0367] #12 /usr/lib/samba/libtevent.so.0(+0x643a) [0x7f38e9ff043a] #13 /usr/lib/samba/libtevent.so.0(+0x655f) [0x7f38e9ff055f] #14 /usr/lib/samba/libtevent.so.0(tevent_common_loop_immediate+0x1f5) [0x7f38e9fef77c] #15 /usr/lib/samba/libtevent.so.0(+0xe19a) [0x7f38e9ff819a] #16 /usr/lib/samba/libtevent.so.0(+0xb11e) [0x7f38e9ff511e] #17 /usr/lib/samba/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f38e9fee8c3] #18 /usr/lib/samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f38e9feeb0d] #19 /usr/lib/samba/libtevent.so.0(+0xb1c0) [0x7f38e9ff51c0] #20 /usr/lib/samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f38e9feebd8] #21 /usr/lib/samba/libsmbd-base-samba4.so(smbd_process+0xc3b) [0x7f38eab99f34] #22 smbd(+0xdd16) [0x7f38eb906d16] #23 /usr/lib/samba/libtevent.so.0(+0xdc16) [0x7f38e9ff7c16] #24 /usr/lib/samba/libtevent.so.0(+0xe234) [0x7f38e9ff8234] #25 /usr/lib/samba/libtevent.so.0(+0xb11e) [0x7f38e9ff511e] #26 /usr/lib/samba/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f38e9fee8c3] #27 /usr/lib/samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f38e9feeb0d] #28 /usr/lib/samba/libtevent.so.0(+0xb1c0) [0x7f38e9ff51c0] #29 /usr/lib/samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f38e9feebd8] #30 smbd(+0xeb26) [0x7f38eb907b26] #31 smbd(main+0x189c) [0x7f38eb909579] #32 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f38e6e44f45] #33 smbd(+0x68b9) [0x7f38eb8ff8b9] (gdb) bt #0 0x00007f38e6e59c37 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #1 0x00007f38e6e5d028 in __GI_abort () at abort.c:89 #2 0x00007f38e8574f1a in dump_core () at ../source3/lib/dumpcore.c:322 #3 0x00007f38e855f49a in smb_panic_s3 (why=0x7f38eb098cad "internal error") at ../source3/lib/util.c:822 #4 0x00007f38eb04814d in smb_panic (why=0x7f38eb098cad "internal error") at ../lib/util/fault.c:166 #5 0x00007f38eb047e25 in fault_report (sig=11) at ../lib/util/fault.c:83 #6 0x00007f38eb047e3a in sig_fault (sig=11) at ../lib/util/fault.c:94 #7 <signal handler called> #8 0x00007f38eabb7bf1 in smbd_smb2_request_reply_update_counts (req=0x7f38ed3a1d20) at ../source3/smbd/smb2_server.c:2731 #9 0x00007f38eabb7e50 in smbd_smb2_request_reply (req=0x7f38ed3a1d20) at ../source3/smbd/smb2_server.c:2754 #10 0x00007f38eabb9638 in smbd_smb2_request_done_ex (req=0x7f38ed3a1d20, status=..., body=..., dyn=0x7fffe4be1d10, location=0x7f38ead5a450 "../source3/smbd/smb2_server.c:3189") at ../source3/smbd/smb2_server.c:3116 #11 0x00007f38eabb993a in smbd_smb2_request_error_ex (req=0x7f38ed3a1d20, status=..., info=0x7fffe4be1d10, location=0x7f38ead64708 "../source3/smbd/smb2_notify.c:125") at ../source3/smbd/smb2_server.c:3189 #12 0x00007f38eabda205 in smbd_smb2_request_notify_done (subreq=0x0) at ../source3/smbd/smb2_notify.c:125 #13 0x00007f38e9ff0367 in _tevent_req_notify_callback (req=0x7f38ed3a2bc0, location=0x7f38ead64b40 "../source3/smbd/smb2_notify.c:360") at ../lib/tevent/tevent_req.c:120 #14 0x00007f38e9ff043a in tevent_req_finish (req=0x7f38ed3a2bc0, state=TEVENT_REQ_USER_ERROR, location=0x7f38ead64b40 "../source3/smbd/smb2_notify.c:360") at ../lib/tevent/tevent_req.c:157 #15 0x00007f38e9ff055f in tevent_req_trigger (ev=0x7f38ed3850a0, im=0x7f38ed3a2ca0, private_data=0x7f38ed3a2bc0) at ../lib/tevent/tevent_req.c:214 #16 0x00007f38e9fef77c in tevent_common_loop_immediate (ev=0x7f38ed3850a0) at ../lib/tevent/tevent_immediate.c:135 #17 0x00007f38e9ff819a in epoll_event_loop_once (ev=0x7f38ed3850a0, location=0x7f38ead51848 "../source3/smbd/process.c:4125") at ../lib/tevent/tevent_epoll.c:907 #18 0x00007f38e9ff511e in std_event_loop_once (ev=0x7f38ed3850a0, location=0x7f38ead51848 "../source3/smbd/process.c:4125") at ../lib/tevent/tevent_standard.c:114 #19 0x00007f38e9fee8c3 in _tevent_loop_once (ev=0x7f38ed3850a0, location=0x7f38ead51848 "../source3/smbd/process.c:4125") at ../lib/tevent/tevent.c:533 #20 0x00007f38e9feeb0d in tevent_common_loop_wait (ev=0x7f38ed3850a0, location=0x7f38ead51848 "../source3/smbd/process.c:4125") at ../lib/tevent/tevent.c:637 #21 0x00007f38e9ff51c0 in std_event_loop_wait (ev=0x7f38ed3850a0, location=0x7f38ead51848 "../source3/smbd/process.c:4125") at ../lib/tevent/tevent_standard.c:145 #22 0x00007f38e9feebd8 in _tevent_loop_wait (ev=0x7f38ed3850a0, location=0x7f38ead51848 "../source3/smbd/process.c:4125") at ../lib/tevent/tevent.c:656 #23 0x00007f38eab99f34 in smbd_process (ev_ctx=0x7f38ed3850a0, msg_ctx=0x7f38ed385690, sock_fd=38, interactive=false) at ../source3/smbd/process.c:4125 #24 0x00007f38eb906d16 in smbd_accept_connection (ev=0x7f38ed3850a0, fde=0x7f38ed39c040, flags=1, private_data=0x7f38ed39ba70) at ../source3/smbd/server.c:1023 #25 0x00007f38e9ff7c16 in epoll_event_loop (epoll_ev=0x7f38ed385600, tvalp=0x7fffe4be2280) at ../lib/tevent/tevent_epoll.c:728 #26 0x00007f38e9ff8234 in epoll_event_loop_once (ev=0x7f38ed3850a0, location=0x7f38eb90d2b7 "../source3/smbd/server.c:1390") at ../lib/tevent/tevent_epoll.c:926 #27 0x00007f38e9ff511e in std_event_loop_once (ev=0x7f38ed3850a0, location=0x7f38eb90d2b7 "../source3/smbd/server.c:1390") at ../lib/tevent/tevent_standard.c:114 #28 0x00007f38e9fee8c3 in _tevent_loop_once (ev=0x7f38ed3850a0, location=0x7f38eb90d2b7 "../source3/smbd/server.c:1390") at ../lib/tevent/tevent.c:533 #29 0x00007f38e9feeb0d in tevent_common_loop_wait (ev=0x7f38ed3850a0, location=0x7f38eb90d2b7 "../source3/smbd/server.c:1390") at ../lib/tevent/tevent.c:637 #30 0x00007f38e9ff51c0 in std_event_loop_wait (ev=0x7f38ed3850a0, location=0x7f38eb90d2b7 "../source3/smbd/server.c:1390") at ../lib/tevent/tevent_standard.c:145 #31 0x00007f38e9feebd8 in _tevent_loop_wait (ev=0x7f38ed3850a0, location=0x7f38eb90d2b7 "../source3/smbd/server.c:1390") at ../lib/tevent/tevent.c:656 #32 0x00007f38eb907b26 in smbd_parent_loop (ev_ctx=0x7f38ed3850a0, parent=0x7f38ed38b940) at ../source3/smbd/server.c:1390 #33 0x00007f38eb909579 in main (argc=2, argv=0x7fffe4be2888) at ../source3/smbd/server.c:2051 (gdb) f 8 #8 0x00007f38eabb7bf1 in smbd_smb2_request_reply_update_counts (req=0x7f38ed3a1d20) at ../source3/smbd/smb2_server.c:2731 2731 if (op->global->channel_sequence == channel_sequence) { (gdb) p op $1 = (struct smbXsrv_open *) 0x4141414141414141 (gdb) p req->compat_chain_fsp $2 = (struct files_struct *) 0x7f38ed3ba6f0 (gdb) p req->compat_chain_fsp->op $3 = (struct smbXsrv_open *) 0x4141414141414141 Shouldn't remove_smb2_chained_fsp() in file_free() be called unconditionally?
Do you have a minimal reproducer ? I think I see what the patch should be for this but I'd really like to watch it happen and create a regression test for this. Thanks, Jeremy.
Hi Jeremy, I did the following test: 1. Enabled talloc_fill by adding "env TALLOC_FREE_FILL=65" into smbd upstart job. 2. Connect to the share: C:\Windows\System32>net use t: \\170.70.2.104\vol1 The command completed successfully. 3. Send OP_NOTIFY request: PS C:\> $watcher = New-Object System.IO.FileSystemWatcher PS C:\> $watcher.Path = "t:\" PS C:\> Register-ObjectEvent $watcher "Created" 4. Force close share: # smbcontrol all close-share vol1 Hope this helps, Lev.
Hi Jeremy, Did you get to try Lev's repro steps? I think this bug always existed. With the introduction of this patch https://lists.samba.org/archive/samba-technical/2016-March/112955.html, this bug shows up because smbd_smb2_request_reply_update_counts() now uses chained-fsp. As Lev suggests, looks like we must always do remove_smb2_chained_fsp() from file_free(). Thanks. --Shyam
(In reply to Shyam Kaushik from comment #3) Yep, got the reproducer working up at the Windows plugfest thanks ! Looking at the fix now.
Created attachment 13298 [details] git-am fix for master Based on Lev's suggestion. Fixes the problem in my testing here. Can you confirm and then we'll get this into master ? Thanks, Jeremy.
Hi Jeremy, Yes, the patch solves the issue. Thanks, Lev.
Created attachment 13301 [details] git-am fix for 4.6.next, 4.5.next. Cherry-picked from master.
Reassigning to Karolin for inclusion in 4.5 and 4.6.
(In reply to Ralph Böhme from comment #8) Pushed to autobuild-v4-6-test. Does not apply on current v4-5-test (source3/smbd/files.c:552).
Oh, looks like this already got pushed to 4.5.next in f3e22f561b09ab89b121032b7453cd2a7ec3ca3f (not sure by who), so I think we're good to go.