[Samba] Help with Possible Bug in Samba 4.1.5 on Connection Close

Thu Mar 13 10:54:30 MDT 2014

I've got a CTDB 2.5.2 Samba 4.1.5 cluster where I'm seeing smbd processes 
using too much CPU after the client connection is closed.  Doing a truss 
against the smbd processes shows nothing during this time, so no syscalls 
seem to be involved.  I rebuilt with debug enabled and took stack traces 
from an offending process spaces about 1 minute apart.  Can anyone from 
the team tell me if this is something I should open a bugzilla for?  Also 
any pointers for debugging this either way would be appreciated.

Right now log level is set to 2 and there isn't anything interesting in 
the log.  I can up the log level to 10 after I find a process in this 
state but the only additions to the log are regarding messageing_tdb 
signals.  These additions are not frequent so I think most of the code 
paths using CPU must not be logging anything.

[2014/03/13 11:32:13.773740,  2, pid=10420472] 
../source3/smbd/service.c:848(make_connection_snum)
  adminib-pci1d7e (ipv4:9.42.212.29:60447) connect to service rtp 
initially as user jbcummin (uid=12443, gid=211) (pid 10420472)
[2014/03/13 12:23:33.530533,  1, pid=10420472] 
../source3/smbd/service.c:1122(close_cnum)
  adminib-pci1d7e (ipv4:9.42.212.29:60447) closed connection to service 
rtp

stack 1:
gettimeofday(??, ??) at 0xd0223d00
GetTimeOfDay(tval = 0x2ff20d80), line 54 in "time.c"
timeval_current(), line 542 in "time.c"
smbXsrv_session_close_loop(subreq = 0x2000cde8), line 243 in 
"smbXsrv_session.c"
_tevent_req_notify_callback(req = 0x2000cde8, location = 
"../source3/lib/msg_channel.c:234"), line 101 in "tevent_req.c"
tevent_req_finish(req = 0x2000cde8, state = TEVENT_REQ_USER_ERROR, 
location = "../source3/lib/msg_channel.c:234"), line 110 in "tevent_req.c"
tevent_req_trigger(ev = 0x2000b2f8, im = 0x200c1528, private_data = 
0x2000cde8), line 166 in "tevent_req.c"
tevent_common_loop_immediate(ev = 0x2000b2f8), line 135 in 
"tevent_immediate.c"
run_events_poll(ev = 0x2000b2f8, pollrtn = 0, pfds = (nil), num_pfds = 0), 
line 192 in "events.c"
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 303 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 530 in "tevent.c"
smbd_process(ev_ctx = 0x2000b2f8, msg_ctx = 0x2000b378, sock_fd = 40, 
interactive = @0x00000000), line 3626 in "process.c"
unnamed block in smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, 
flags = 1, private_data = 0x200c1548), line 621 in "server.c"
smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, flags = 1, 
private_data = 0x200c1548), line 621 in "server.c"
unnamed block in run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 
0x200148a8, num_pfds = 7), line 257 in "events.c"
run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 0x200148a8, num_pfds 
= 7), line 257 in "events.c"
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 326 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 530 in "tevent.c"
unnamed block in smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 
0x2000e6e8), line 943 in "server.c"
smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 0x2000e6e8), line 943 in 
"server.c"
server.main(argc = 2, argv = 0x2ff22b54), line 1577 in "server.c"

stack 2:
_talloc_free_internal(ptr = 0x2000cde8, location = 
"../source3/smbd/smbXsrv_session.c:247"), line 840 in "talloc.c"
_talloc_free(ptr = 0x2000cde8, location = 
"../source3/smbd/smbXsrv_session.c:247"), line 1489 in "talloc.c"
smbXsrv_session_close_loop(subreq = 0x2000cde8), line 247 in 
"smbXsrv_session.c"
_tevent_req_notify_callback(req = 0x2000cde8, location = 
"../source3/lib/msg_channel.c:234"), line 101 in "tevent_req.c"
tevent_req_finish(req = 0x2000cde8, state = TEVENT_REQ_USER_ERROR, 
location = "../source3/lib/msg_channel.c:234"), line 110 in "tevent_req.c"
tevent_req_trigger(ev = 0x2000b2f8, im = 0x200c1528, private_data = 
0x2000cde8), line 166 in "tevent_req.c"
tevent_common_loop_immediate(ev = 0x2000b2f8), line 135 in 
"tevent_immediate.c"
run_events_poll(ev = 0x2000b2f8, pollrtn = 0, pfds = (nil), num_pfds = 0), 
line 192 in "events.c"
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 303 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 530 in "tevent.c"
smbd_process(ev_ctx = 0x2000b2f8, msg_ctx = 0x2000b378, sock_fd = 40, 
interactive = @0x00000000), line 3626 in "process.c"
unnamed block in smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, 
flags = 1, private_data = 0x200c1548), line 621 in "server.c"
smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, flags = 1, 
private_data = 0x200c1548), line 621 in "server.c"
unnamed block in run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 
0x200148a8, num_pfds = 7), line 257 in "events.c"
run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 0x200148a8, num_pfds 
= 7), line 257 in "events.c"
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 326 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 530 in "tevent.c"
unnamed block in smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 
0x2000e6e8), line 943 in "server.c"
smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 0x2000e6e8), line 943 in 
"server.c"
server.main(argc = 2, argv = 0x2ff22b54), line 1577 in "server.c"

stack 3:
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 328 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 530 in "tevent.c"
smbd_process(ev_ctx = 0x2000b2f8, msg_ctx = 0x2000b378, sock_fd = 40, 
interactive = @0x00000000), line 3626 in "process.c"
unnamed block in smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, 
flags = 1, private_data = 0x200c1548), line 621 in "server.c"
smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, flags = 1, 
private_data = 0x200c1548), line 621 in "server.c"
unnamed block in run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 
0x200148a8, num_pfds = 7), line 257 in "events.c"
run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 0x200148a8, num_pfds 
= 7), line 257 in "events.c"
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 326 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 530 in "tevent.c"
unnamed block in smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 
0x2000e6e8), line 943 in "server.c"
smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 0x2000e6e8), line 943 in 
"server.c"
server.main(argc = 2, argv = 0x2ff22b54), line 1577 in "server.c"

stack 4:
_talloc_free_internal(ptr = 0x2000dca8, location = 
"../source3/smbd/smbXsrv_session.c:247"), line 892 in "talloc.c"
unnamed block in _talloc_free_children_internal(tc = 0x2000cdb8, ptr = 
0x2000cde8, location = "../source3/smbd/smbXsrv_session.c:247"), line 1374 
in "talloc.c"
_talloc_free_children_internal(tc = 0x2000cdb8, ptr = 0x2000cde8, location 
= "../source3/smbd/smbXsrv_session.c:247"), line 1374 in "talloc.c"
_talloc_free_internal(ptr = 0x2000cde8, location = 
"../source3/smbd/smbXsrv_session.c:247"), line 904 in "talloc.c"
_talloc_free(ptr = 0x2000cde8, location = 
"../source3/smbd/smbXsrv_session.c:247"), line 1489 in "talloc.c"
smbXsrv_session_close_loop(subreq = 0x2000cde8), line 247 in 
"smbXsrv_session.c"
_tevent_req_notify_callback(req = 0x2000cde8, location = 
"../source3/lib/msg_channel.c:234"), line 101 in "tevent_req.c"
tevent_req_finish(req = 0x2000cde8, state = TEVENT_REQ_USER_ERROR, 
location = "../source3/lib/msg_channel.c:234"), line 110 in "tevent_req.c"
tevent_req_trigger(ev = 0x2000b2f8, im = 0x200c1528, private_data = 
0x2000cde8), line 166 in "tevent_req.c"
tevent_common_loop_immediate(ev = 0x2000b2f8), line 135 in 
"tevent_immediate.c"
run_events_poll(ev = 0x2000b2f8, pollrtn = 0, pfds = (nil), num_pfds = 0), 
line 192 in "events.c"
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 303 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/process.c:3626"), line 530 in "tevent.c"
smbd_process(ev_ctx = 0x2000b2f8, msg_ctx = 0x2000b378, sock_fd = 40, 
interactive = @0x00000000), line 3626 in "process.c"
unnamed block in smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, 
flags = 1, private_data = 0x200c1548), line 621 in "server.c"
smbd_accept_connection(ev = 0x2000b2f8, fde = 0x200c1598, flags = 1, 
private_data = 0x200c1548), line 621 in "server.c"
unnamed block in run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 
0x200148a8, num_pfds = 7), line 257 in "events.c"
run_events_poll(ev = 0x2000b2f8, pollrtn = 1, pfds = 0x200148a8, num_pfds 
= 7), line 257 in "events.c"
s3_event_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 326 in "events.c"
_tevent_loop_once(ev = 0x2000b2f8, location = 
"../source3/smbd/server.c:943"), line 530 in "tevent.c"
unnamed block in smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 
0x2000e6e8), line 943 in "server.c"
smbd_parent_loop(ev_ctx = 0x2000b2f8, parent = 0x2000e6e8), line 943 in 
"server.c"
server.main(argc = 2, argv = 0x2ff22b54), line 1577 in "server.c"

John Janosik
jpjanosi at us.ibm.com