[Samba] FreeBSD-Samba 4.16: local user login fails when Active Directory domain joined
Dave Baukus
daveb at spectralogic.com
Thu Sep 28 19:25:01 UTC 2023
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
>
More information about the samba
mailing list