Why the communication between winbindd child and DC is not asynchronous?
Pavel Filipensky
pfilipen at redhat.com
Tue Aug 17 08:00:02 UTC 2021
Hi,
I have noticed "winbindd: domain child [ADDOMAIN]" is able to start
processing of the next incoming request from the main winbindd only after
the response from the DC is received. This was reproduced in
ad_member_idmap_rid selftest environment via running:
id ADDOMAIN/user1 & id ADDOMAIN/user2 & id ADDOMAIN/user3 &
To make the sequence of events clearly visible, the DC processing is made
slower using 1 sec delay before each incoming request is started - using
gdb breakpoint:
b lsarpc__op_dispatch
commands
shell sleep 1
c
end
The main winbind traces show the all incoming requests (*in:)* are
processed within the first second (07:21:13) and the responses (*out:*) are
coming later ((07:21:14, 07:21:15, 07:21:16):
[2021/08/17 07:21:13.315813, 1, id=29, pid=1017618, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
in: struct wbint_LookupName
[2021/08/17 07:21:13.321539, 1, id=32, pid=1017618, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
in: struct wbint_LookupName
[2021/08/17 07:21:13.321942, 1, id=33, pid=1017618, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
in: struct wbint_LookupName
[2021/08/17 07:21:14.524244, 1, id=29, pid=1017618, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
out: struct wbint_LookupName
[2021/08/17 07:21:15.555467, 1, id=29, pid=1017618, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
out: struct wbint_LookupName
[2021/08/17 07:21:16.583586, 1, id=29, pid=1017618, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
out: struct wbint_LookupName
The traces from child show that the incoming request from main winbindd can
be processed only after the response from DC is delivered:
[2021/08/17 07:21:13.316195, 1, id=0, pid=1017624, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
in: struct wbint_LookupName
[2021/08/17 07:21:14.523416, 1, id=0, pid=1017624, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
out: struct wbint_LookupName
[2021/08/17 07:21:14.526129, 1, id=0, pid=1017624, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
in: struct wbint_LookupName
[2021/08/17 07:21:15.554392, 1, id=0, pid=1017624, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
out: struct wbint_LookupName
[2021/08/17 07:21:15.556991, 1, id=0, pid=1017624, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
in: struct wbint_LookupName
[2021/08/17 07:21:16.582744, 1, id=0, pid=1017624, effective(0, 0),
real(0, 0), class=rpc_parse]
../../librpc/ndr/ndr.c:484(ndr_print_function_debug)
out: struct wbint_LookupName
The reason for this is that we have inner (frame #4) and outer (frame #27)
tevent loop in the winbindd child when it waits for DC to respond. The
outer loop used for processing of incoming requests is blocked till the
inner loop gets the response:
#0 epoll_wait () from /lib64/libc.so.6
#1 epoll_event_loop (epoll_ev=0x5619e41014c0, tvalp=0x7ffc90bb0ed0) at
glib/tevent/tevent_epoll.c:650
#2 epoll_event_loop_once (ev=0x5619e4199940, location=0x7f832cdb19e0
"glib/tevent/tevent_req.c:300") at glib/tevent/tevent_epoll.c:937
#3 std_event_loop_once (ev=0x5619e4199940, location=0x7f832cdb19e0
"glib/tevent/tevent_req.c:300") at glib/tevent/tevent_standard.c:110
#4 _tevent_loop_once (ev=0x5619e4199940, location=0x7f832cdb19e0
"glib/tevent/tevent_req.c:300") at glib/tevent/tevent.c:790
#5 tevent_req_poll (req=0x5619e418c5e0, ev=0x5619e4199940) at
glib/tevent/tevent_req.c:300
#6 tevent_req_poll_ntstatus (req=0x5619e418c5e0, ev=0x5619e4199940,
status=0x7ffc90bb1024) at glib/util/tevent_ntstatus.c:109
#7 dcerpc_binding_handle_call (h=0x5619e4199730, object=0x0,
table=0x7f832c0e4340 <ndr_table_lsarpc>, opnum=77, r_mem=0x5619e411bdc0,
r_ptr=0x7ffc90bb10d0) at glibrpc/rpc/binding_handle.c:560
#8 dcerpc_lsa_LookupNames4_r (h=0x5619e4199730, mem_ctx=0x5619e411bdc0,
r=0x7ffc90bb10d0) at librpc/gen_ndr/ndr_lsa_c.c:13483
#9 dcerpc_lsa_LookupNames4 (h=0x5619e4199730, mem_ctx=0x5619e411bdc0,
_num_names=1, _names=0x5619e4199530, _domains=0x7ffc90bb11c8,
_sids=0x7ffc90bb11a0, _level=LSA_LOOKUP_NAMES_DOMAINS_ONLY,
_count=0x7ffc90bb119c,
_lookup_options=LSA_LOOKUP_OPTION_SEARCH_ISOLATED_NAMES,
_client_revision=LSA_CLIENT_REVISION_2, result=0x7ffc90bb1280) at
librpc/gen_ndr/ndr_lsa_c.c:13645
#10 dcerpc_lsa_lookup_names_generic (h=0x5619e4199730,
mem_ctx=0x5619e411bdc0, pol=0x7ffc90bb1260, num_names=1,
names=0x7ffc90bb1310, dom_names=0x7ffc90bb1308,
level=LSA_LOOKUP_NAMES_DOMAINS_ONLY, sids=0x7ffc90bb1320,
types=0x7ffc90bb1318, use_lookupnames4=true, presult=0x7ffc90bb1280) at
gsource3/rpc_client/cli_lsarpc.c:588
#11 winbindd_lookup_names (mem_ctx=0x5619e411bdc0, domain=0x5619e4109630,
num_names=1, names=0x7ffc90bb1310, domains=0x7ffc90bb1308,
sids=0x7ffc90bb1320, types=0x7ffc90bb1318) at
gsource3/winbindd/winbindd_msrpc.c:1021
#12 msrpc_name_to_sid (domain=0x5619e4109630, mem_ctx=0x5619e411bdc0,
domain_name=0x5619e417fa00 "ADDOMAIN", name=0x5619e4177330 "BOB5", flags=8,
pdom_name=0x7ffc90bb1448, sid=0x5619e4107520, type=0x5619e417a6c0) at
gsource3/winbindd/winbindd_msrpc.c:264
#13 name_to_sid (domain=0x5619e4109630, mem_ctx=0x5619e411bdc0,
domain_name=0x5619e417fa00 "ADDOMAIN", name=0x5619e4177330 "BOB5", flags=8,
pdom_name=0x7ffc90bb1448, sid=0x5619e4107520, type=0x5619e417a6c0) at
gsource3/winbindd/winbindd_ads.c:569
#14 name_to_sid (domain=0x5619e4109630, mem_ctx=0x5619e411bdc0,
domain_name=0x5619e417fa00 "ADDOMAIN", name=0x5619e4177330 "BOB5", flags=8,
pdom_name=0x7ffc90bb1448, sid=0x5619e4107520, type=0x5619e417a6c0) at
gsource3/winbindd/winbindd_reconnect_ads.c:146
#15 wb_cache_name_to_sid (domain=0x5619e4109630, mem_ctx=0x5619e411bdc0,
domain_name=0x5619e417fa00 "ADDOMAIN", name=0x5619e4177330 "BOB5", flags=8,
sid=0x5619e4107520, type=0x5619e417a6c0) at
gsource3/winbindd/winbindd_cache.c:1803
#16 _wbint_LookupName (p=0x5619e4119f50, r=0x5619e411c7a0) at
gsource3/winbindd/winbindd_dual_srv.c:142
#17 winbind__op_dispatch_internal (dce_call=0x5619e411bdc0,
mem_ctx=0x5619e411bdc0, r=0x5619e411c7a0,
dispatch=S3COMPAT_RPC_DISPATCH_INTERNAL) at
./librpc/gen_ndr/ndr_winbind_scompat.c:186
#18 winbind__op_local (dce_call=0x5619e411bdc0, mem_ctx=0x5619e411bdc0,
r=0x5619e411c7a0) at ./librpc/gen_ndr/ndr_winbind_scompat.c:876
#19 dcesrv_call_dispatch_local (call=0x5619e411bdc0) at
glibrpc/rpc/dcesrv_core.c:2983
#20 winbindd_dual_ndrcmd (domain=0x5619e4109630, state=0x7ffc90bb3108) at
gsource3/winbindd/winbindd_dual_ndr.c:553
#21 child_process_request (child=0x5619e4109890, state=0x7ffc90bb3108) at
gsource3/winbindd/winbindd_dual.c:791
#22 child_handler (ev=0x5619e40e73b0, fde=0x5619e411c580, flags=1,
private_data=0x7ffc90bb3100) at gsource3/winbindd/winbindd_dual.c:1669
#23 tevent_common_invoke_fd_handler (fde=0x5619e411c580, flags=1,
removed=0x0) at glib/tevent/tevent_fd.c:142
#24 epoll_event_loop (epoll_ev=0x5619e4109410, tvalp=0x7ffc90bb1820) at
glib/tevent/tevent_epoll.c:736
#25 epoll_event_loop_once (ev=0x5619e40e73b0, location=0x5619e3a3ffb8
"gsource3/winbindd/winbindd_dual.c:1896") at glib/tevent/tevent_epoll.c:937
#26 std_event_loop_once (ev=0x5619e40e73b0, location=0x5619e3a3ffb8
"gsource3/winbindd/winbindd_dual.c:1896") at
glib/tevent/tevent_standard.c:110
#27 _tevent_loop_once (ev=0x5619e40e73b0, location=0x5619e3a3ffb8
"gsource3/winbindd/winbindd_dual.c:1896") at glib/tevent/tevent.c:790
#28 fork_domain_child (child=0x5619e4109890) at
gsource3/winbindd/winbindd_dual.c:1896
#29 wb_child_request_waited (subreq=0x0) at
gsource3/winbindd/winbindd_dual.c:271
#30 _tevent_req_notify_callback (req=0x5619e411cac0,
location=0x7f832cdb1790 "glib/tevent/tevent_queue.c:355") at
glib/tevent/tevent_req.c:141
#31 tevent_req_finish (req=0x5619e411cac0, state=TEVENT_REQ_DONE,
location=0x7f832cdb1790 "glib/tevent/tevent_queue.c:355") at
glib/tevent/tevent_req.c:193
#32 _tevent_req_done (req=0x5619e411cac0, location=0x7f832cdb1790
"glib/tevent/tevent_queue.c:355") at glib/tevent/tevent_req.c:199
#33 tevent_queue_wait_trigger (req=0x5619e411cac0, private_data=0x0) at
glib/tevent/tevent_queue.c:355
#34 tevent_queue_immediate_trigger (ev=0x5619e40e73b0, im=0x5619e410a320,
private_data=0x5619e410a280) at glib/tevent/tevent_queue.c:149
#35 tevent_common_invoke_immediate_handler (im=0x5619e410a320, removed=0x0)
at glib/tevent/tevent_immediate.c:190
#36 tevent_common_loop_immediate (ev=0x5619e40e73b0) at
glib/tevent/tevent_immediate.c:236
#37 epoll_event_loop_once (ev=0x5619e40e73b0, location=0x5619e3a13900
"gsource3/winbindd/winbindd.c:2030") at glib/tevent/tevent_epoll.c:918
#38 std_event_loop_once (ev=0x5619e40e73b0, location=0x5619e3a13900
"gsource3/winbindd/winbindd.c:2030") at glib/tevent/tevent_standard.c:110
#39 _tevent_loop_once (ev=0x5619e40e73b0, location=0x5619e3a13900
"gsource3/winbindd/winbindd.c:2030") at glib/tevent/tevent.c:790
#40 main (argc=7, argv=0x7ffc90bb3868) at gsource3/winbindd/winbindd.c:2030
I assume that this is an unwanted situation, since the purpose of tevent
library is to achieve asynchronous communication, or? Can we get rid of the
inner tevent loop which starts in dcerpc_binding_handle_call()? I am
wondering what is this TODO comment (from commit 4030bc9b) about:
528 NTSTATUS dcerpc_binding_handle_call(struct dcerpc_binding_handle *h,
...
541 »·······/ * TODO: allow only one sync call
Pavel
More information about the samba-technical
mailing list