access after free in srvsvc client

Wed Nov 14 10:52:44 UTC 2018

This is reliably reproducible under conditions that may be hard to reproduce.

With about 8000 client processes running on a single machine, each producing a
unique semi-realistic sequence of requests aimed at a Windows machine that is
beginning to creak under the load, a dozen or so of the 8000 clients will
crash like this:

talloc: access after free error - first free may be at ../lib/tevent/tevent_req.c:289
Bad talloc magic value - access after free
===============================================================
INTERNAL ERROR: Signal 6 in pid 28839 (4.10.0pre1-DEVELOPERBUILD)
Please read the Trouble-Shooting section of the Samba HOWTO
===============================================================
smb_panic_default: PANIC (pid 28839): internal error
BACKTRACE: 64 stack frames:
 #0 /home/ubuntu/samba/bin/shared/libsamba-util.so.0(log_stack_trace+0x2e) [0x7fd24427ebf3]
 #1 /home/ubuntu/samba/bin/shared/libsamba-util.so.0(+0x20969) [0x7fd24427e969]
 #2 /home/ubuntu/samba/bin/shared/libsamba-util.so.0(log_stack_trace+0) [0x7fd24427ebc5]
 #3 /home/ubuntu/samba/bin/shared/libsamba-util.so.0(+0x20869) [0x7fd24427e869]
 #4 /home/ubuntu/samba/bin/shared/libsamba-util.so.0(+0x2087e) [0x7fd24427e87e]
 #5 /lib/x86_64-linux-gnu/libc.so.6(+0x3ef20) [0x7fd2474e6f20]
 #6 /lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7) [0x7fd2474e6e97]
 #7 /lib/x86_64-linux-gnu/libc.so.6(abort+0x141) [0x7fd2474e8801]
 #8 /home/ubuntu/samba/bin/shared/private/libtalloc.so.2(+0x293f) [0x7fd2452f493f]
 #9 /home/ubuntu/samba/bin/shared/private/libtalloc.so.2(+0x2962) [0x7fd2452f4962]
 #10 /home/ubuntu/samba/bin/shared/private/libtalloc.so.2(+0x29e7) [0x7fd2452f49e7]
 #11 /home/ubuntu/samba/bin/shared/private/libtalloc.so.2(+0x2d94) [0x7fd2452f4d94]
 #12 /home/ubuntu/samba/bin/shared/private/libtalloc.so.2(+0x2fa8) [0x7fd2452f4fa8]
 #13 /home/ubuntu/samba/bin/shared/private/libtalloc.so.2(+0x3373) [0x7fd2452f5373]
 #14 /home/ubuntu/samba/bin/shared/private/libtalloc.so.2(_talloc_memdup+0x2f) [0x7fd2452f7ff5]
 #15 /home/ubuntu/samba/bin/shared/libsamba-util.so.0(data_blob_talloc_named+0x7a) [0x7fd24427870d]
 #16 /home/ubuntu/samba/bin/shared/private/libgensec-samba4.so(+0x22960) [0x7fd23f2eb960]
 #17 /home/ubuntu/samba/bin/shared/private/libgensec-samba4.so(+0x240db) [0x7fd23f2ed0db]
 #18 /home/ubuntu/samba/bin/shared/private/libgensec-samba4.so(gensec_update_send+0x166) [0x7fd23f2e699b]
 #19 /home/ubuntu/samba/bin/shared/private/libgensec-samba4.so(+0xec16) [0x7fd23f2d7c16]
 #20 /home/ubuntu/samba/bin/shared/private/libgensec-samba4.so(gensec_update_send+0x166) [0x7fd23f2e699b]
 #21 /home/ubuntu/samba/bin/shared/private/libsmbclient-raw-samba4.so(+0x3658b) [0x7fd23ff7c58b]
 #22 /home/ubuntu/samba/bin/shared/private/libsmbclient-raw-samba4.so(smb2_session_setup_spnego_send+0x569) [0x7fd23ff7c4a1]
 #23 /home/ubuntu/samba/bin/shared/private/libsmbclient-raw-samba4.so(+0x39ba6) [0x7fd23ff7fba6]
 #24 /home/ubuntu/samba/bin/shared/private/libsmbclient-raw-samba4.so(smb2_connect_send+0x2bf) [0x7fd23ff7f777]
 #25 /home/ubuntu/samba/bin/shared/libdcerpc.so.0(+0x25048) [0x7fd241dda048]
 #26 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7fd244b656c2]
 #27 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(+0x8823) [0x7fd244b65823]
 #28 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(_tevent_req_done+0x25) [0x7fd244b65850]
 #29 /home/ubuntu/samba/bin/shared/private/libsmbclient-raw-samba4.so(+0x2cbd2) [0x7fd23ff72bd2]
 #30 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7fd244b656c2]
 #31 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(+0x8823) [0x7fd244b65823]
 #32 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(_tevent_req_done+0x25) [0x7fd244b65850]
 #33 /home/ubuntu/samba/bin/shared/private/libcli-smb-common-samba4.so(+0x18d7e) [0x7fd23ec93d7e]
 #34 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7fd244b656c2]
 #35 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(+0x8823) [0x7fd244b65823]
 #36 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(+0x8950) [0x7fd244b65950]
 #37 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(tevent_common_invoke_immediate_handler+0x184) [0x7fd244b645c5]
 #38 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(tevent_common_loop_immediate+0x37) [0x7fd244b646cb]
 #39 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(+0x11d50) [0x7fd244b6ed50]
 #40 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(+0xe5f6) [0x7fd244b6b5f6]
 #41 /home/ubuntu/samba/bin/shared/private/libtevent.so.0(_tevent_loop_once+0x11e) [0x7fd244b6306f]
 #42 /home/ubuntu/samba/bin/shared/private/libsamba-sockets-samba4.so(composite_wait+0x3b) [0x7fd23e6ab63b]
 #43 /home/ubuntu/samba/bin/shared/libdcerpc.so.0(dcerpc_pipe_connect_recv+0x20) [0x7fd241ddc10b]
 #44 /home/ubuntu/samba/bin/shared/libdcerpc.so.0(dcerpc_pipe_connect+0x5e) [0x7fd241ddc1db]
 #45 /home/ubuntu/samba/bin/shared/private/libsamba-python-samba4.so(py_dcerpc_interface_init_helper+0x8ff) [0x7fd2423ff894]
 #46 bin/python/samba/dcerpc/srvsvc.so(+0xc05f5) [0x7fd232d955f5]
 #47 python(+0xe33d5) [0x56145cb773d5]
 #48 python(PyEval_EvalFrameEx+0x54b0) [0x56145cb8df60]
 [more python frames]

The failing python essentially does this:

    from samba.dcerpc import srvsvc
    srvsvc.srvsvc("ncacn_np:%s" % server, lp, creds)

The client machine doesn't seem to be suffering greatly according to gross metrics
(like CPU, mem, load average, scheduler latency). The same error occurs at the same
load against a Samba server, but it is harder to spot because Samba is groaning so much
as it disintegrates. I am not sure whether it happens at the same rate. At lower loads
the frequency drops off dramatically.

What I *think* is going on is something in the smb2 layer has decided to finish up
and free the request, assuming gensec will be finished when it isn't. But smb, tevent,
gensec -- these are not things I know well. Does anyone have any pointers?

Below is the slightly more informative gdb stack trace.

Douglas

#0  0x00007fd24758c9a4 in __GI___nanosleep (requested_time=0x7fffe828af00, remaining=0x7fffe828af00)
    at ../sysdeps/unix/sysv/linux/nanosleep.c:28
#1  0x00007fd24758c8aa in __sleep (seconds=0) at ../sysdeps/posix/sleep.c:55
#2  0x00007fd24427e973 in smb_panic_default (why=0x7fd2442d4765 "internal error") at ../lib/util/fault.c:130
#3  0x00007fd24427ebc5 in smb_panic (why=0x7fd2442d4765 "internal error") at ../lib/util/fault.c:173
#4  0x00007fd24427e869 in fault_report (sig=6) at ../lib/util/fault.c:84
#5  0x00007fd24427e87e in sig_fault (sig=6) at ../lib/util/fault.c:95
#6  <signal handler called>
#7  __GI_raise (sig=sig at entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#8  0x00007fd2474e8801 in __GI_abort () at abort.c:79
#9  0x00007fd2452f493f in talloc_abort (reason=0x7fd2452f92b0 "Bad talloc magic value - access after free")
    at ../lib/talloc/talloc.c:500
#10 0x00007fd2452f4962 in talloc_abort_access_after_free () at ../lib/talloc/talloc.c:508
#11 0x00007fd2452f49e7 in talloc_chunk_from_ptr (ptr=0x56145ff48c20) at ../lib/talloc/talloc.c:525
#12 0x00007fd2452f4d94 in __talloc_with_prefix (context=0x56145ff48c20, size=2993, prefix_len=0, tc_ret=0x7fffe828c128)
    at ../lib/talloc/talloc.c:743
#13 0x00007fd2452f4fa8 in __talloc (context=0x56145ff48c20, size=2993, tc=0x7fffe828c128) at ../lib/talloc/talloc.c:804
#14 0x00007fd2452f5373 in _talloc_named_const (context=0x56145ff48c20, size=2993,
    name=0x7fd2442d3bd0 "../lib/util/data_blob.c:54") at ../lib/talloc/talloc.c:961
#15 0x00007fd2452f7ff5 in _talloc_memdup (t=0x56145ff48c20, p=0x5614604546a0, size=2993,
    name=0x7fd2442d3bd0 "../lib/util/data_blob.c:54") at ../lib/talloc/talloc.c:2416
#16 0x00007fd24427870d in data_blob_talloc_named (mem_ctx=0x56145ff48c20, p=0x5614604546a0, length=2993,
    name=0x7fd23f2f7338 "DATA_BLOB: ../source4/auth/gensec/gensec_gssapi.c:695") at ../lib/util/data_blob.c:54
#17 0x00007fd23f2eb960 in gensec_gssapi_update_internal (gensec_security=0x56145ff43be0, out_mem_ctx=0x56145ff48c20,
    ev=0x56146004acd0, in=..., out=0x56145ff48c28) at ../source4/auth/gensec/gensec_gssapi.c:695
#18 0x00007fd23f2ed0db in gensec_gssapi_update_send (mem_ctx=0x56145ff44d80, ev=0x56146004acd0, gensec_security=0x56145ff43be0,
    in=...) at ../source4/auth/gensec/gensec_gssapi.c:1059
#19 0x00007fd23f2e699b in gensec_update_send (mem_ctx=0x561460443f20, ev=0x56146004acd0, gensec_security=0x56145ff43be0, in=...)
    at ../auth/gensec/gensec.c:433
#20 0x00007fd23f2d7c16 in gensec_spnego_update_send (mem_ctx=0x56145ff3c120, ev=0x56146004acd0, gensec_security=0x5614604562a0,
    in=...) at ../auth/gensec/spnego.c:1722
#21 0x00007fd23f2e699b in gensec_update_send (mem_ctx=0x56145ff55900, ev=0x56146004acd0, gensec_security=0x5614604562a0, in=...)
    at ../auth/gensec/gensec.c:433
#22 0x00007fd23ff7c58b in smb2_session_setup_spnego_gensec_next (req=0x56145ff55750) at ../source4/libcli/smb2/session.c:253
#23 0x00007fd23ff7c4a1 in smb2_session_setup_spnego_send (mem_ctx=0x56145ee52a80, ev=0x56146004acd0, session=0x56146004a710,
    credentials=0x56145edbac40, previous_session_id=0) at ../source4/libcli/smb2/session.c:232
#24 0x00007fd23ff7fba6 in smb2_connect_session_start (req=0x56145ee528d0) at ../source4/libcli/smb2/connect.c:221
#25 0x00007fd23ff7f777 in smb2_connect_send (mem_ctx=0x5614601464d0, ev=0x56146004acd0, host=0x56146003b7b0 "",
    ports=0x56145f253700, share=0x7fd241de842b "IPC$", resolve_ctx=0x561460455e80, credentials=0x56145edbac40,
    fallback_to_anonymous=false, existing_conn=0x561460146500, previous_session_id=0, options=0x561460146520,
    socket_options=0x56145f251680 "TCP_NODELAY", gensec_settings=0x561460444510) at ../source4/libcli/smb2/connect.c:125
#26 0x00007fd241dda048 in continue_smbXcli_connect (subreq=0x0) at ../source4/librpc/rpc/dcerpc_connect.c:275
#27 0x00007fd244b656c2 in _tevent_req_notify_callback (req=0x561460458790,
    location=0x7fd23ff89fb8 "../source4/libcli/smb_composite/connect_nego.c:189") at ../lib/tevent/tevent_req.c:139
#28 0x00007fd244b65823 in tevent_req_finish (req=0x561460458790, state=TEVENT_REQ_DONE,
    location=0x7fd23ff89fb8 "../source4/libcli/smb_composite/connect_nego.c:189") at ../lib/tevent/tevent_req.c:191
#29 0x00007fd244b65850 in _tevent_req_done (req=0x561460458790,
    location=0x7fd23ff89fb8 "../source4/libcli/smb_composite/connect_nego.c:189") at ../lib/tevent/tevent_req.c:197
#30 0x00007fd23ff72bd2 in smb_connect_nego_nego_done (subreq=0x0) at ../source4/libcli/smb_composite/connect_nego.c:189
#31 0x00007fd244b656c2 in _tevent_req_notify_callback (req=0x56146001f070,
    location=0x7fd23ecab900 "../libcli/smb/smbXcli_base.c:4935") at ../lib/tevent/tevent_req.c:139
#32 0x00007fd244b65823 in tevent_req_finish (req=0x56146001f070, state=TEVENT_REQ_DONE,
    location=0x7fd23ecab900 "../libcli/smb/smbXcli_base.c:4935") at ../lib/tevent/tevent_req.c:191
#33 0x00007fd244b65850 in _tevent_req_done (req=0x56146001f070, location=0x7fd23ecab900 "../libcli/smb/smbXcli_base.c:4935")
    at ../lib/tevent/tevent_req.c:197
#34 0x00007fd23ec93d7e in smbXcli_negprot_smb2_done (subreq=0x0) at ../libcli/smb/smbXcli_base.c:4935
#35 0x00007fd244b656c2 in _tevent_req_notify_callback (req=0x5614600377f0,
    location=0x7fd23ecaae60 "../libcli/smb/smbXcli_base.c:3937") at ../lib/tevent/tevent_req.c:139
#36 0x00007fd244b65823 in tevent_req_finish (req=0x5614600377f0, state=TEVENT_REQ_DONE,
    location=0x7fd23ecaae60 "../libcli/smb/smbXcli_base.c:3937") at ../lib/tevent/tevent_req.c:191
#37 0x00007fd244b65950 in tevent_req_trigger (ev=0x56146004acd0, im=0x5614600378e0, private_data=0x5614600377f0)
    at ../lib/tevent/tevent_req.c:248
#38 0x00007fd244b645c5 in tevent_common_invoke_immediate_handler (im=0x5614600378e0, removed=0x0)
    at ../lib/tevent/tevent_immediate.c:165
#39 0x00007fd244b646cb in tevent_common_loop_immediate (ev=0x56146004acd0) at ../lib/tevent/tevent_immediate.c:202
#40 0x00007fd244b6ed50 in epoll_event_loop_once (ev=0x56146004acd0,
    location=0x7fd23e6b9690 "../source4/libcli/composite/composite.c:58") at ../lib/tevent/tevent_epoll.c:918
#41 0x00007fd244b6b5f6 in std_event_loop_once (ev=0x56146004acd0,
    location=0x7fd23e6b9690 "../source4/libcli/composite/composite.c:58") at ../lib/tevent/tevent_standard.c:110
#42 0x00007fd244b6306f in _tevent_loop_once (ev=0x56146004acd0,
    location=0x7fd23e6b9690 "../source4/libcli/composite/composite.c:58") at ../lib/tevent/tevent.c:772
#43 0x00007fd23e6ab63b in composite_wait (c=0x56146004b910) at ../source4/libcli/composite/composite.c:58
#44 0x00007fd241ddc10b in dcerpc_pipe_connect_recv (c=0x56146004b910, mem_ctx=0x561460456d80, pp=0x7fd22f32f390)
    at ../source4/librpc/rpc/dcerpc_connect.c:1217
#45 0x00007fd241ddc1db in dcerpc_pipe_connect (parent_ctx=0x561460456d80, pp=0x7fd22f32f390,
    binding=0x7fd22f337f04 "ncacn_np:WIN-3O0IOFFICGJ.samdom.example.com", table=0x7fd23e477ae0 <ndr_table_srvsvc>,
    credentials=0x56145edbac40, ev=0x56146004acd0, lp_ctx=0x56145f090720) at ../source4/librpc/rpc/dcerpc_connect.c:1242
#46 0x00007fd2423ff894 in py_dcerpc_interface_init_helper (type=0x7fd232fdbd20 <srvsvc_InterfaceType>,
    args=('ncacn_np:WIN-3O0IOFFICGJ.samdom.example.com', <param.LoadParm at remote 0x7fd2329f8a80>, <credentials.Credentials at remote 0x7fd22f32f260>), kwargs=0x0,
table=0x7fd23e477ae0 <ndr_table_srvsvc>) at ../source4/librpc/rpc/pyrpc_util.c:217
#47 0x00007fd232d955f5 in interface_srvsvc_new (type=0x7fd232fdbd20 <srvsvc_InterfaceType>,
    args=('ncacn_np:WIN-3O0IOFFICGJ.samdom.example.com', <param.LoadParm at remote 0x7fd2329f8a80>, <credentials.Credentials at remote 0x7fd22f32f260>), kwargs=0x0) at
default/librpc/gen_ndr/py_srvsvc.c:63471
#48 0x000056145cb7#49 0x000056145cb8df60 in PyObject_Call (kw=0x0,
    arg=('ncacn_np:WIN-3O0IOFFICGJ.samdom.example.com', <param.LoadParm at remote 0x7fd2329f8a80>, <credentials.Credentials at remote 0x7fd22f32f260>), func=<optimized out>)
at ../Objects/abstract.c:2547