winbindd callbacks not triggered

[Rowland penny]

On 28/09/2020 09:51, Isaac Boukris via samba-technical wrote:
> Hi,
>
> I'm looking into a customer issue which i couldn't reproduce, they are
> running v4.10.4 (i didn't find any recent related fixes), and report
> that when winbindd runs for a while it becomes slow to respond and
> commands like 'id root' may take more than a minute.
>
> The first thing that caught my eyes is this one time error I see in
> log.winbindd, of which looks quite strange:
>
> [2020/09/02 07:04:35.886276,  0, pid=42540, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/wb_lookupsids.c:663(wb_lookupsids_recv)
>    res_names->count = 2, expected 3
> [2020/09/02 07:04:35.886322,  5, pid=42540, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/wb_sids2xids.c:426(wb_sids2xids_recv)
>    wb_sids_to_xids failed: NT_STATUS_INTERNAL_ERROR
>
> But the real issue is with requests that seem to get lost and for
> which the callbacks do not seem to be triggered, for example:
>
> [2020/09/01 20:12:01.603270,  6, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd.c:920(new_connection)
>    accepted socket 32
> [2020/09/01 20:12:01.603329, 10, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd.c:768(process_request_send)
>    process_request_send: process_request: request fn INTERFACE_VERSION
> [2020/09/01 20:12:01.603346,  3, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd_misc.c:432(winbindd_interface_version)
>    winbindd_interface_version: [nss_winbind (19519)]: request interface
> version (version = 31)
> [2020/09/01 20:12:01.603376, 10, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd.c:854(process_request_written)
>    process_request_written: [nss_winbind(19519):unknown request]:
> delivered response to client
> [2020/09/01 20:12:01.603441, 10, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd.c:744(process_request_send)
>    process_request_send: process_request: Handling async request
> nss_winbind(19519):GETGROUPS
> [2020/09/01 20:12:01.603460,  3, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd_getgroups.c:66(winbindd_getgroups_send)
>    winbindd_getgroups_send: [nss_winbind (19519)] getgroups root
> [2020/09/01 20:12:01.603723, 10, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/wb_sids2xids.c:114(wb_sids2xids_send)
>    SID 0: S-1-22-1-0
> [2020/09/01 20:12:01.603767, 10, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd_util.c:1462(find_lookup_domain_from_sid)
>    find_lookup_domain_from_sid: SID [S-1-22-1-0]
>
> And that's it, after that winbindd goes back to the main loop and
> handles another request, notice the pid (some times after several
> seconds like here, which shows that winbind is rather idle, sometimes
> immediately):
>
> [2020/09/01 20:12:13.111935,  6, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd.c:920(new_connection)
>    accepted socket 29
>
> Reviewing the code flow from wb_sids2xids_send() it is not clear why
> it doesn't get it from cache, but mostly I could not make sense of
> these logs (assuming level 10), that is I expect to see more printouts
> before winbind goes back to the event loop...
>
> Then after a minute we get this (lp_winbind_request_timeout):
>
> [2020/09/01 20:13:02.700696,  5, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd.c:1212(remove_timed_out_clients)
>    Client request timed out, shutting down sock 32, pid 19519
>
> Or sometimes the client gives up first, and we see some like this:
>
> [2020/09/01 20:13:05.144441,  6, pid=15783, effective(0, 0), real(0,
> 0), class=winbind]
> ../../source3/winbindd/winbindd.c:1019(winbind_client_activity)
>    winbind_client_activity[19583:GETGROUPS]: client has closed
> connection - removing client
>
> Thoughts?
>
> Thanks!
>
Sounds to me like a misconfiguration in /etc/nsswitch.conf, running 'id 
root' should check /etc/passwd and /etc/group first. winbind shouldn't 
even be consulted.

Rowland