samba - Sep 2023 - FreeBSD-Samba 4.16: local user login fails when Active Directory domain joined

Just to close out this thread, in case anyone has the same problem, the issue
is/was https://bugzilla.samba.org/show_bug.cgi?id=15361
Porting/Coercing the 4.17 patches to 4.16 fixed this crazy issue.

Dave Baukus

On 8/23/23 16:21, Dave Baukus wrote:
> A minor clue.
> When I first start samba_server and after the domain is joined, I can
briefly log in; I can keep logging in as long as the number of
usr/local/libexec/samba/rpcd_lsad processes is 2:
>
> #? ps -axfH -w -o pid,ppid,flags,stat,rss,cputime,etime,mwchan,args | grep
samba | grep -v grep
> 87024???? 1 10000001 Ss??? 25652????? 0:00.02??????? 01:03 select??
/usr/local/libexec/samba/samba-dcerpcd --libexec-rpcds --ready-signal-fd=21
--np-helper --debuglevel=1
> 87034 87024 10004101 S???? 29972????? 0:00.11??????? 01:02 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=5 --debuglev
> 87175 87024 10004101 S???? 29880????? 0:00.11??????? 00:29 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=6 --debuglev
>
> #? ps -axfH -w -o pid,ppid,flags,stat,rss,cputime,etime,mwchan,args | grep
samba | grep -v grep | wc -l
> ?????? 3
>
> Then something goes wrong and the number of rpcd_lsad processes keeps
slowly increasing (seemingly topping out at 9) and I can no longer login:
>
> #? ps -axfH -w -o pid,ppid,flags,stat,rss,cputime,etime,mwchan,args | grep
samba | grep -v grep | wc -l
> ?????? 9
> #? ps -axfH -w -o pid,ppid,flags,stat,rss,cputime,etime,mwchan,args | grep
samba | grep -v grep
> 87024???? 1 10000001 Ss??? 25652????? 0:00.08??????? 09:57 select??
/usr/local/libexec/samba/samba-dcerpcd --libexec-rpcds --ready-signal-fd=21
--np-helper --debuglevel=1
> 87034 87024 10004101 S???? 30052????? 0:00.13??????? 09:56 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=5 --debuglev
> 87175 87024 10004101 S???? 30040????? 0:00.12??????? 09:23 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=6 --debuglev
> 87630 87024 10004101 S???? 30020????? 0:00.12??????? 07:20 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=7 --debuglev
> 87667 87024 10004101 S???? 30016????? 0:00.12??????? 07:10 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=8 --debuglev
> 87710 87024 10004101 S???? 30040????? 0:00.12??????? 07:00 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=9 --debuglev
> 87773 87024 10004101 S???? 30064????? 0:00.12??????? 06:39 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=10 --debugle
> 87814 87024 10004101 S???? 30060????? 0:00.12??????? 06:19 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=11 --debugle
> 88365 87024 10004101 I???? 29980????? 0:00.11??????? 02:56 select??
/usr/local/libexec/samba/rpcd_lsad --configfile=/usr/local/etc/smb4.conf
--worker-group=4 --worker-index=12 --debugle
>
>
> Dave Baukus
> On 8/23/23 15:34, Dave Baukus wrote:
>> Recently upgraded from Samba 4.13 to 4.16 on a FreeBSD stable 13.2
platform.
>> When I join a domain I cannot log on as myself as a local unix user via
ssh as I was able to do with samba 4.13.
>> When this occurs, the login prompt does not appear for a long time (60
seconds or more) by which time it is too late to enter.
>> My pam configuration has not changed.
>>
>> When the domain is joined, the logs begin are spammed with the
following:
>>
>> Aug 23 19:32:45 winbindd[54994]: [2023/08/23 19:32:45.229571, 1]
../../source3/winbindd/winbindd_dual.c:363(wb_child_request_cleanup)
>> Aug 23 19:32:45 winbindd[54994]:?? wb_child_request_cleanup: keep
orphaned subreq[0x1104cbbd2200]
>> Aug 23 19:32:45 samba-dcerpcd[55003]: [2023/08/23 19:32:45.698848,? 1]
../../source3/rpc_server/rpc_host.c:1353(rpc_host_distribute_clients)
>> Aug 23 19:32:45 samba-dcerpcd[55003]: rpc_host_distribute_clients:
Sending new client /usr/local/libexec/samba/rpcd_lsad to 55084 with 0 clients
>> Aug 23 19:32:45 samba-dcerpcd[55003]: [2023/08/23 19:32:45.700050,? 1]
../../source3/rpc_server/rpc_host.c:1353(rpc_host_distribute_clients)
>> Aug 23 19:32:45 samba-dcerpcd[55003]: rpc_host_distribute_clients:
Sending new client /usr/local/libexec/samba/rpcd_lsad to 55248 with 0 clients
>> Aug 23 19:32:55 winbindd[54994]: [2023/08/23 19:32:55.841898, 1]
../../source3/winbindd/winbindd_dual.c:306(wb_child_request_orphaned)
>> Aug 23 19:32:55 winbindd[54994]:?? wb_child_request_orphaned: cleanup
orphaned subreq[0x1104cbbd2200]
>>
>> Increased verbosity shows:
>>
>> Aug 23 21:23:03 winbindd[75515]: [2023/08/23 21:23:03.173561, 0]
../../source3/winbindd/winbindd.c:1061(winbind_client_processed)
>> Aug 23 21:23:03 winbindd[75515]:?? winbind_client_processed: request
took 63.167713 seconds
>> Aug 23 21:23:03 winbindd[75515]:?? [struct process_request_state]
../../source3/winbindd/winbindd.c:675 [2023/08/23 21:22:00.005840]
../../source3/winbindd/winbindd.c:856 [2023/08/23 21:23:03.173553] [63.167713]
-> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:??? [struct winbindd_getgroups_state]
../../source3/winbindd/winbindd_getgroups.c:54 [2023/08/23 21:22:00.005844]
../../source3/winbindd/winbindd_getgroups.c:111 [2023/08/23 21:23:03.173529]
[63.167685] -> TEVENT_REQ_USER_ERROR (3 10483072397370982515))
>> Aug 23 21:23:03 winbindd[75515]:???? [struct wb_lookupname_state]
../../source3/winbindd/wb_lookupname.c:47 [2023/08/23 21:22:00.005855]
../../source3/winbindd/wb_lookupname.c:95 [2023/08/23 21:23:03.173527]
[63.167672] -> TEVENT_REQ_USER_ERROR (3 10483072397370982515))
>> Aug 23 21:23:03 winbindd[75515]:????? [struct
dcerpc_wbint_LookupName_state] librpc/gen_ndr/ndr_winbind_c.c:781 [2023/08/23
21:22:00.005862] librpc/gen_ndr/ndr_winbind_c.c:847 [2023/08/23 21:23:03.173526]
[63.167664] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:?????? [struct
dcerpc_wbint_LookupName_r_state] librpc/gen_ndr/ndr_winbind_c.c:693 [2023/08/23
21:22:00.005864] librpc/gen_ndr/ndr_winbind_c.c:727 [2023/08/23 21:23:03.173524]
[63.167660] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:??????? [struct
dcerpc_binding_handle_call_state] ../../librpc/rpc/binding_handle.c:371
[2023/08/23 21:22:00.005866] ../../librpc/rpc/binding_handle.c:520 [2023/08/23
21:23:03.173521] [63.167655] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:???????? [struct
dcerpc_binding_handle_raw_call_state] ../../librpc/rpc/binding_handle.c:149
[2023/08/23 21:22:00.005876] ../../librpc/rpc/binding_handle.c:203 [2023/08/23
21:23:03.173516] [63.167640] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:????????? [struct
wbint_bh_raw_call_state] ../../source3/winbindd/winbindd_dual_ndr.c:93
[2023/08/23 21:22:00.005879] ../../source3/winbindd/winbindd_dual_ndr.c:208
[2023/08/23 21:23:03.173514] [63.167635] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:?????????? [struct
wb_domain_request_state] ../../source3/winbindd/winbindd_dual.c:499 [2023/08/23
21:22:00.005883] ../../source3/winbindd/winbindd_dual.c:734 [2023/08/23
21:23:03.173507] [63.167624] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:??????????? [struct
wb_child_request_state] ../../source3/winbindd/winbindd_dual.c:198 [2023/08/23
21:23:03.170852] ../../source3/winbindd/winbindd_dual.c:298 [2023/08/23
21:23:03.173506] [0.002654] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:???????????? [struct
tevent_queue_wait_state] ../../tevent_queue.c:350 [2023/08/23 21:23:03.170854]
../../tevent_queue.c:369 [2023/08/23 21:23:03.170856] [0.000002] ->
TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:???????????? [struct
wb_simple_trans_state] ../../nsswitch/wb_reqtrans.c:375 [2023/08/23
21:23:03.170859] ../../nsswitch/wb_reqtrans.c:432 [2023/08/23 21:23:03.173503]
[0.002644] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:????????????? [struct req_write_state]
../../nsswitch/wb_reqtrans.c:158 [2023/08/23 21:23:03.170859]
../../nsswitch/wb_reqtrans.c:194 [2023/08/23 21:23:03.170880] [0.000021] ->
TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:?????????????? [struct writev_state]
../../lib/async_req/async_sock.c:267 [2023/08/23 21:23:03.170860]
../../lib/async_req/async_sock.c:373 [2023/08/23 21:23:03.170879] [0.000019]
-> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:????????????? [struct resp_read_state]
../../nsswitch/wb_reqtrans.c:222 [2023/08/23 21:23:03.170882]
../../nsswitch/wb_reqtrans.c:275 [2023/08/23 21:23:03.173503] [0.002621] ->
TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:?????????????? [struct
read_packet_state] ../../lib/async_req/async_sock.c:480 [2023/08/23
21:23:03.170883] ../../lib/async_req/async_sock.c:568 [2023/08/23
21:23:03.173501] [0.002618] -> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]:??? [struct resp_write_state]
../../nsswitch/wb_reqtrans.c:307 [2023/08/23 21:23:03.173533]
../../nsswitch/wb_reqtrans.c:344 [2023/08/23 21:23:03.173551] [0.000018] ->
TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 sm4u-11 winbindd[75515]:???? [struct writev_state]
../../lib/async_req/async_sock.c:267 [2023/08/23 21:23:03.173534]
../../lib/async_req/async_sock.c:373 [2023/08/23 21:23:03.173543] [0.000009]
-> TEVENT_REQ_DONE (2 0))
>> Aug 23 21:23:03 winbindd[75515]: [2023/08/23 21:23:03.174437, 1]
../../source3/winbindd/winbindd_dual.c:363(wb_child_request_cleanup)
>> Aug 23 21:23:03 winbindd[75515]:?? wb_child_request_cleanup: keep
orphaned subreq[0x10338ddc5300]
>>
>>
>> I'm at loss on how to debug this; any clues would be appreciated
>>
>>
>> My pam.d/sshd is:
>>
>> # auth
>> auth??????????? sufficient????? pam_opie.so no_warn no_fake_prompts
>> auth??????????? requisite?????? pam_opieaccess.so no_warn allow_local
>> auth????????? ? sufficient????? pam_winbind.so????????? debug
try_first_pass require_membership_of=BUILTIN\\Users
>> auth??????????? required??????? pam_unix.so no_warn use_first_pass
nullok
>>
>> # account
>> account???????? required??????? pam_nologin.so
>> account???????? required??????? pam_login_access.so
>> account???????? required??????? pam_unix.so
>>
>> # session
>> session???????? required??????? pam_winbind.so????????? debug krb5_auth
>> session???????? required??????? pam_permit.so
>>
>> # password
>> password??????? sufficient????? pam_winbind.so????????? debug
>> password??????? required??????? pam_unix.so no_warn try_first_pass
>>
>>
>>
>> My smb4.conf is:
>>
>> [global]
>> include = /etc/smbver.conf
>> ??????? printcap name = /dev/null
>> ??????? load printers = no
>> ??????? disable spoolss = yes
>> ??????? ntlm auth = ntlmv2-only
>> ??????? strict sync = yes
>> ??????? deadtime = 15
>> ??????? hide dot files = no
>> ??????? template homedir = /usr/home
>> ??????? template shell = /usr/local/bin/shellcli
>> ??????? force unknown acl user = yes
>> ??????? guest account = guest
>> ??????? kernel oplocks = no
>> ??????? eventlog list = Application Security System
>> ??????? max log size = 0
>> ??????? logging = syslog file at 0
>> ??????? log level = 1
>> ??????? vfs objects = acl_xattr streams_depot freebsd
>> ??????? freebsd:extattr mode = legacy
>> ??????? acl_xattr:ignore system acls = yes
>> ??????? acl_xattr:default acl style = windows
>> ??????? ea support = yes
>> ??????? streams_depot:delete_lost = yes
>> ??????? store dos attributes = yes
>> ??????? veto files = /:STREAM/
>> ??????? registry shares = yes
>> ??????? idmap config * : backend = autorid
>> ??????? idmap config * : rangesize = 1000000
>> ??????? idmap config * : range = 1000000-19999999
>> ??????? bind interfaces only = yes
>> ??????? security = ads
>> ??????? workgroup = XXX
>> ??????? realm = XXX.LOCAL
>> ??????? allow trusted domains = no
>>
>> -- 
>> Dave Baukus
>