FreeBSD-Samba 4.16: local user login fails when Active Directory domain joined
Dave Baukus
daveb at spectralogic.com
Thu Aug 24 17:33:44 UTC 2023
I Recently upgraded from Samba 4.13 to 4.16 on a FreeBSD stable 13.2 platform.
When I join a domain there is a brief period in which I can log on as myself as a local unix user via ssh, but after an indeterminate period all such attempts fail.
When the login attempts fail, a prompt does not appear for over 60 seconds by which time it is too late to enter the password (ssh gives up ?).
My pam configuration has not changed.
I have noticed that when I can login there are 2 rpcd_lsad processes running:
# 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
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
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
When the domain is joined, the logs are being 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 or get this working; 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-technical
mailing list