[Samba] Fwd: PAM Offline Authentication in Ubuntu 22.04...

Sat Jun 3 18:45:09 UTC 2023


On 03/06/2023 19:12, Kees van Vloten via samba wrote:
> 
> On 03-06-2023 16:57, Rowland Penny via samba wrote:
>>
>>
>> On 03/06/2023 12:27, Kees van Vloten via samba wrote:
>>>
>>> However for a lookup with the command 'id' pam_winbind is irrelevant 
>>> since we only do a user and group lookup, it is nss-winbind that is 
>>> being used.
>>>
>>> I don't see any differences between our smb.conf file that could 
>>> cause this issue, do you?
>>>
>>> I guess the next thing to try is increase log level to a high value 
>>> and repeat the test, any other ideas?
>>>
>>> - Kees.
>>
>> When you logon it is pam_winbind that is used, from my tests there is 
>> just one line different in /var/log/auth.log between having the 
>> network connected or not at logon
>> Without the network, I get this extra line:
>>
>> May 28 08:20:59 member1 lightdm: pam_winbind(lightdm:auth): User 
>> rowland logged on using cached credentials
>>
>> If you use gdm3, you get a similar line.
> I understand that, however the test with 'id testuser' does not do 
> authentication. SInce it already reproduces the issue that rules out any 
> issues with pam_winbind. Therefore it must be an issue in nss_winbind.
>>
>> By all means try a higher log level, but my gut feeling is that it is 
>> something at the OS level that is creating the wait.
>>
>> Rowland
>>
>>
> I ran both connected and disconnected 'id testuser' through strace and 
> in smb.conf: "log level 3 winbind:10"
> 
> The first 200 lines are left away since they are equal in both situation.
> 
> strace id testuser connected:
> 
> mprotect(0x7fa1cf90f000, 4096, PROT_READ) = 0
> mprotect(0x7fa1cf925000, 4096, PROT_READ) = 0
> mprotect(0x7fa1cf939000, 4096, PROT_READ) = 0
> munmap(0x7fa1cff3d000, 122599)          = 0
> getpid()                                = 1961
> getpid()                                = 1961
> getpid()                                = 1961
> futex(0x7fa1cfca20c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
> lstat("/run/samba/winbindd", {st_mode=S_IFDIR|0755, st_size=60, ...}) = 0
> lstat("/run/samba/winbindd/pipe", {st_mode=S_IFSOCK|0777, st_size=0, 
> ...}) = 0
> socket(AF_UNIX, SOCK_STREAM, 0)         = 3
> fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)
> fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
> fcntl(3, F_GETFD)                       = 0
> fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
> connect(3, {sa_family=AF_UNIX, sun_path="/run/samba/winbindd/pipe"}, 
> 110) = 0
> getpid()                                = 1961
> getpid()                                = 1961
> poll([{fd=3, events=POLLIN|POLLOUT|POLLHUP}], 1, -1) = 1 ([{fd=3, 
> revents=POLLOUT}])
> write(3, 
> "X\10\0\0\0\0\0\0\0\0\0\0\251\7\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2136) = 2136
> getpid()                                = 1961
> poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3, 
> revents=POLLIN}])
> read(3, "\250\17\0\0\2\0\0\0 
> \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4008) = 4008
> poll([{fd=3, events=POLLIN|POLLOUT|POLLHUP}], 1, -1) = 1 ([{fd=3, 
> revents=POLLOUT}])
> write(3, 
> "X\10\0\0\1\0\0\0\0\0\0\0\251\7\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 
> 2136) = 2136
> getpid()                                = 1961
> poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3, 
> revents=POLLIN}])
> read(3, 
> "\250\17\0\0\2\0\0\0kvv\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 
> 4008) = 4008
> openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
> lseek(4, 0, SEEK_CUR)                   = 0
> fstat(4, {st_mode=S_IFREG|0644, st_size=2475, ...}) = 0
> read(4, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2475
> 
> strace -tt id testuser disconnected and ctrl-c where it "hangs":
> 
> 19:42:47.526437 mprotect(0x7ff2bc581000, 4096, PROT_READ) = 0
> 19:42:47.526499 mprotect(0x7ff2bc597000, 4096, PROT_READ) = 0
> 19:42:47.526548 mprotect(0x7ff2bc5ab000, 4096, PROT_READ) = 0
> 19:42:47.526594 munmap(0x7ff2bcbaf000, 122599) = 0
> 19:42:47.526660 getpid()                = 3979
> 19:42:47.526699 getpid()                = 3979
> 19:42:47.526733 getpid()                = 3979
> 19:42:47.526771 futex(0x7ff2bc9140c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
> 19:42:47.526856 lstat("/run/samba/winbindd", {st_mode=S_IFDIR|0755, 
> st_size=60, ...}) = 0
> 19:42:47.526928 lstat("/run/samba/winbindd/pipe", 
> {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
> 19:42:47.526970 socket(AF_UNIX, SOCK_STREAM, 0) = 3
> 19:42:47.527007 fcntl(3, F_GETFL)       = 0x2 (flags O_RDWR)
> 19:42:47.527062 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
> 19:42:47.527127 fcntl(3, F_GETFD)       = 0
> 19:42:47.527174 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
> 19:42:47.527210 connect(3, {sa_family=AF_UNIX, 
> sun_path="/run/samba/winbindd/pipe"}, 110) = 0
> 19:42:47.527396 getpid()                = 3979
> 19:42:47.527502 getpid()                = 3979
> 19:42:47.527553 poll([{fd=3, events=POLLIN|POLLOUT|POLLHUP}], 1, -1) = 1 
> ([{fd=3, revents=POLLOUT}])
> 19:42:47.527653 write(3, 
> "X\10\0\0\0\0\0\0\0\0\0\0\213\17\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2136) = 2136
> 19:42:47.527817 getpid()                = 3979
> 19:42:47.527852 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 
> ([{fd=3, revents=POLLIN}])
> 19:42:47.527895 read(3, "\250\17\0\0\2\0\0\0 
> \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4008) = 4008
> 19:42:47.527938 poll([{fd=3, events=POLLIN|POLLOUT|POLLHUP}], 1, -1) = 1 
> ([{fd=3, revents=POLLOUT}])
> 19:42:47.527979 write(3, 
> "X\10\0\0\1\0\0\0\0\0\0\0\213\17\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2136) = 2136
> 19:42:47.528428 getpid()                = 3979
> 19:42:47.528465 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 0 
> (Timeout)
> 19:42:52.531442 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 0 
> (Timeout)
> 19:42:57.537318 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 0 
> (Timeout)
> 19:43:02.544018 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = ? 
> ERESTART_RESTARTBLOCK (Interrupted by signal)
> 19:43:02.711306 --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
> 19:43:02.711867 +++ killed by SIGINT +++
> 
> log.wb-SAMDOM show the domain is reported offline before "id testuser" 
> is started
> 
> [2023/06/03 19:40:06.824113,  0, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_cache.c:3464(set_global_winbindd_state_offline)
>    set_global_winbindd_state_offline: Offline requested
> [2023/06/03 19:40:06.824140, 10, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/winbindd_cm.c:163(set_domain_offline)
>    set_domain_offline: called for domain SAMDOM
> [2023/06/03 19:40:06.824175, 10, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/winbindd_cm.c:163(set_domain_offline)
>    set_domain_offline: called for domain SAMDOM
> [2023/06/03 19:40:06.824205, 10, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_cache.c:1794(wcache_name_to_sid)
>    wcache_name_to_sid: namemap_cache_find_name failed
> [2023/06/03 19:40:06.824216,  4, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/winbindd_dual.c:1641(child_handler)
>    Finished processing child request 55
> [2023/06/03 19:40:06.824222, 10, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_dual.c:159(child_write_response)
>    Writing 4024 bytes to parent
> [2023/06/03 19:42:37.973329, 10, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_cm.c:3284(winbind_msg_ip_dropped)
>    IP 192.168.1.108 dropped
> [2023/06/03 19:42:37.973344, 10, pid=2926, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_cm.c:3284(winbind_msg_ip_dropped)
>    IP fe80::3f67:f5b0:e1ca:720d dropped
> 
> log.winbindd-idmap:
> 
> [2023/06/03 19:42:47.528286, 10, pid=2782, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_dual.c:124(child_read_request)
>    Need to read 214 extra bytes
> [2023/06/03 19:42:47.528301,  4, pid=2782, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/winbindd_dual.c:1633(child_handler)
>    child daemon request 55
> [2023/06/03 19:42:47.528307, 10, pid=2782, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_dual_ndr.c:538(winbindd_dual_ndrcmd)
>    winbindd_dual_ndrcmd: Running command wbint_GetNssInfo (domain '(null)')
> [2023/06/03 19:42:47.528338, 10, pid=2782, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/idmap_ad.c:532(idmap_ad_query_user)
>    idmap_ad_query_user: Filter: 
> [(objectsid=\01\05\00\00\00\00\00\05\15\00\00\00\FB'\BF\F9.lc\D8\C5\CF]y\CD\04\00\00)]
> [2023/06/03 19:42:47.528357, 10, pid=2782, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/idmap_ad.c:289(idmap_ad_tldap_debug)
>    idmap_ad_tldap: tldap_msg_send: sending msg 29
> ============ THIS IS WHERE THE TIMEOUT IN STRACE HAPPENS ============
> 
> log.winbindd
> 
> [2023/06/03 19:42:47.528012,  3, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/winbindd.c:496(process_request_send)
>    process_request_send: [nss_winbind (3979)] Handling async request: 
> GETPWNAM
> [2023/06/03 19:42:47.528022,  3, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_getpwnam.c:59(winbindd_getpwnam_send)
>    [nss_winbind (3979)] Winbind external command GETPWNAM start.
>    Query username 'testuser'.
> [2023/06/03 19:42:47.528032,  5, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_lookupname.c:52(wb_lookupname_send)
>    WB command lookupname start.
>    Search namespace 'SAMDOM' and domain 'SAMDOM' for name 'testuser'.
> [2023/06/03 19:42:47.528062, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_dual_ndr.c:112(wbint_bh_raw_call_send)
>    wbint_bh_raw_call_send: Got opnum 3 for domain SAMDOM from cache
> [2023/06/03 19:42:47.528077,  5, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_lookupname.c:118(wb_lookupname_recv)
>    WB command lookupname end.
>    Found SID S-1-5-21-4190054395-3630394414-2036191173-1229 with SID 
> type 1.
> [2023/06/03 19:42:47.528088,  5, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/wb_getpwsid.c:49(wb_getpwsid_send)
>    WB command getpwsid start.
>    Query user SID S-1-5-21-4190054395-3630394414-2036191173-1229.
> [2023/06/03 19:42:47.528096,  5, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/wb_queryuser.c:56(wb_queryuser_send)
>    WB command queryuser start.
>    Query user sid S-1-5-21-4190054395-3630394414-2036191173-1229
> [2023/06/03 19:42:47.528107, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:95(wb_queryuser_idmap_setup_done)
>    Convert the user SID S-1-5-21-4190054395-3630394414-2036191173-1229 
> to XID.
> [2023/06/03 19:42:47.528113,  5, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/wb_sids2xids.c:84(wb_sids2xids_send)
>    WB command sids2xids start.
>    Resolving 1 SID(s).
> [2023/06/03 19:42:47.528120, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/wb_sids2xids.c:156(wb_sids2xids_send)
>    0: SID S-1-5-21-4190054395-3630394414-2036191173-1229
> [2023/06/03 19:42:47.528141, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/wb_sids2xids.c:175(wb_sids2xids_send)
>    Found 1 (out of 1) SID(s) in cache.
> [2023/06/03 19:42:47.528152,  5, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/wb_sids2xids.c:775(wb_sids2xids_recv)
>    WB command sids2xids end.
> [2023/06/03 19:42:47.528157,  5, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/wb_sids2xids.c:779(wb_sids2xids_recv)
>    0: Found XID 1104 for SID S-1-5-21-4190054395-3630394414-2036191173-1229
> [2023/06/03 19:42:47.528163, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:134(wb_queryuser_got_uid)
>    Received XID 1104 for SID 
> S-1-5-21-4190054395-3630394414-2036191173-1229.
> [2023/06/03 19:42:47.528169, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:148(wb_queryuser_got_uid)
> [2023/06/03 19:42:47.528169, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:148(wb_queryuser_got_uid)
>    Preconfigured 'Domain Users' RID 513 was used to create group SID 
> S-1-5-21-4190054395-3630394414-2036191173-513 from user SID 
> S-1-5-21-4190054395-3630394414-2036191173-1229.
> [2023/06/03 19:42:47.528176, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:154(wb_queryuser_got_uid)
>    Setting 'homedir' to the template '/home/%U'.
> [2023/06/03 19:42:47.528181, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:160(wb_queryuser_got_uid)
>    Setting 'shell' to the template '/bin/bash'.
> [2023/06/03 19:42:47.528206, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:167(wb_queryuser_got_uid)
>    Filling data received from netsamlogon_cache
>        state->info: struct wbint_userinfo
>            domain_name              : *
>                domain_name              : 'SAMDOM'
>            acct_name                : *
>                acct_name                : 'testuser'
>            full_name                : *
>                full_name                : 'Test User'
>            homedir                  : *
>                homedir                  : '/home/%U'
>            shell                    : *
>                shell                    : '/bin/bash'
>            uid                      : 0x00000000000003ec (1104)
>            primary_gid              : 0x00000000ffffffff (4294967295)
>            primary_group_name       : NULL
>            user_sid                 : 
> S-1-5-21-4190054395-3630394414-2036191173-1229
>            group_sid                : 
> S-1-5-21-4190054395-3630394414-2036191173-513
> [2023/06/03 19:42:47.528248, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/wb_queryuser.c:198(wb_queryuser_got_uid)
>    Domain name is set, calling dcerpc_wbint_GetNssInfo_send()
> ============ THIS IS WHERE THE TIMEOUT IN STRACE HAPPENS ============
> [2023/06/03 19:42:56.059505, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_util.c:715(winbindd_ping_offline_domains)
>    winbindd_ping_offline_domains: Domain BUILTIN is online
> [2023/06/03 19:42:56.059550, 10, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_util.c:720(winbindd_ping_offline_domains)
>    winbindd_ping_offline_domains: We are globally offline, do nothing.
> [2023/06/03 19:43:02.711750,  6, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd.c:772(winbind_client_activity)
>    winbind_client_activity[3979:GETPWNAM]: client has closed connection 
> - removing client
> [2023/06/03 19:43:02.711803,  2, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] ../../source3/winbindd/winbindd.c:884(remove_client)
>    final write to client failed: Broken pipe
> [2023/06/03 19:43:02.711839,  1, pid=2759, effective(0, 0), real(0, 0), 
> class=winbind] 
> ../../source3/winbindd/winbindd_dual.c:370(wb_child_request_cleanup)
>    wb_child_request_cleanup: keep orphaned subreq[0x559ec34dd000]
> 
> Unfortunately I don't see a clear correlation between the strace output 
> and an event in the logging. I guess I have to run a strace on the 
> winbindd pid in parallel to capture the exact thing happening in winbindd.
> 
> 
> - Kees.
> 
> 


I can logon what ever I do, so to me it looks like 'winbind offline 
logon' works, The pause seems to be something else and I tried Eduardo's 
idea 'winbind request timeout' and it does seem to work, I set it to 10 
an the 'real' dropped to 0m11.343s

Rowland