Bug 12818 - smbd panic after connection force close
Summary: smbd panic after connection force close
Status: RESOLVED FIXED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.5.10
Hardware: All All
: P5 normal (vote)
Target Milestone: ---
Assignee: Jeremy Allison
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-06-05 14:42 UTC by Lev
Modified: 2017-06-29 06:44 UTC (History)
2 users (show)

See Also:


Attachments
Full logs (216.05 KB, text/plain)
2017-06-05 14:42 UTC, Lev
no flags Details
git-am fix for master (994 bytes, patch)
2017-06-20 20:04 UTC, Jeremy Allison
no flags Details
git-am fix for 4.6.next, 4.5.next. (1.15 KB, patch)
2017-06-21 22:49 UTC, Jeremy Allison
slow: review+
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Lev 2017-06-05 14:42:12 UTC
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?
Comment 1 Jeremy Allison 2017-06-05 21:09:33 UTC
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.
Comment 2 Lev 2017-06-06 07:20:43 UTC
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.
Comment 3 Shyam Kaushik 2017-06-19 06:12:49 UTC
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
Comment 4 Jeremy Allison 2017-06-20 18:50:01 UTC
(In reply to Shyam Kaushik from comment #3)

Yep, got the reproducer working up at the Windows plugfest thanks !

Looking at the fix now.
Comment 5 Jeremy Allison 2017-06-20 20:04:43 UTC
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.
Comment 6 Lev 2017-06-21 06:19:48 UTC
Hi Jeremy,
Yes, the patch solves the issue.
Thanks,
  Lev.
Comment 7 Jeremy Allison 2017-06-21 22:49:41 UTC
Created attachment 13301 [details]
git-am fix for 4.6.next, 4.5.next.

Cherry-picked from master.
Comment 8 Ralph Böhme 2017-06-28 05:58:39 UTC
Reassigning to Karolin for inclusion in 4.5 and 4.6.
Comment 9 Karolin Seeger 2017-06-28 09:07:09 UTC
(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).
Comment 10 Jeremy Allison 2017-06-28 17:08:52 UTC
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.