[Samba] Fwd: PAM Offline Authentication in Ubuntu 22.04...
Kees van Vloten
keesvanvloten at gmail.com
Sat Jun 3 19:18:46 UTC 2023
On 03-06-2023 20:45, Rowland Penny via samba wrote:
>
>
> 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
That shortens the timeout at least, so looks like a good idea. Will test
what it does for me.
Meanwhile I ran another strace: "strace -tt -p 2759 -o output.txt id
testuser", where 2759 is the pid of /usr/sbin/winbindd (and 4418 is the
pid of "id testuser".
Looking at the previous output I did some correlations, some of the last
lines of the previous strace:
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
\10\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2136) = 2136
getpid() = 2080
poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 0 (Timeout)
The combined strace of "id" and "winbind" starts at the same line as the
above:
4418 20:25:19.455795 <... poll resumed>) = 1 ([{fd=3, revents=POLLOUT}])
2759 20:25:19.455804 <... getpid resumed>) = 2759
4418 20:25:19.455811 write(3,
"X\10\0\0\1\0\0\0\0\0\0\0B\21\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
2136 <unfinished ...>
======= PREVIOUS OUTPUT LINE ===== write(3, "X\10\0\0\1\0\0\0\0\0\0\0
\10\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2136) = 2136 =====
2759 20:25:19.455820 getgid( <unfinished ...>
4418 20:25:19.455829 <... write resumed>) = 2136
2759 20:25:19.455836 <... getgid resumed>) = 0
4418 20:25:19.455842 getpid( <unfinished ...>
2759 20:25:19.455849 getuid( <unfinished ...>
4418 20:25:19.455855 <... getpid resumed>) = 4418
2759 20:25:19.455861 <... getuid resumed>) = 0
4418 20:25:19.455867 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000
<unfinished ...>
2759 20:25:19.455875 getegid() = 0
2759 20:25:19.455906 geteuid() = 0
2759 20:25:19.455939 geteuid() = 0
2759 20:25:19.455970 writev(4, [{iov_base="[2023/06/03 20:25:19.455740,
10,"..., iov_len=150}, {iov_base=" process_request_written: [nss_"...,
iov_len=95}], 2) = 245
2759 20:25:19.456016 epoll_ctl(5, EPOLL_CTL_ADD, 24,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=3276806400, u64=94140370000128}}) = 0
2759 20:25:19.456054 epoll_wait(5, [{EPOLLIN, {u32=3276806400,
u64=94140370000128}}], 1, 464) = 1
2759 20:25:19.456097 recvfrom(24, "X\10\0\0", 4, 0, NULL, NULL) = 4
2759 20:25:19.456141 epoll_wait(5, [{EPOLLIN, {u32=3276806400,
u64=94140370000128}}], 1, 464) = 1
2759 20:25:19.456180 recvfrom(24,
"\1\0\0\0\0\0\0\0B\21\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
2132, 0, NULL, NULL) = 2132
2759 20:25:19.456222 epoll_ctl(5, EPOLL_CTL_DEL, 24, 0x7ffdc769e19c) = 0
2759 20:25:19.456257 epoll_ctl(5, EPOLL_CTL_ADD, 24,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=3276621504, u64=94140369815232}}) = 0
2759 20:25:19.456295 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.456340 getpid() = 2759
2759 20:25:19.456372 getgid() = 0
2759 20:25:19.456405 getuid() = 0
2759 20:25:19.456437 getegid() = 0
2759 20:25:19.456498 geteuid() = 0
2759 20:25:19.456546 geteuid() = 0
2759 20:25:19.456578 writev(4, [{iov_base="[2023/06/03
20:25:19.456288, 3,"..., iov_len=147}, {iov_base="
process_request_send: [nss_win"..., iov_len=78}], 2) = 225
2759 20:25:19.456620 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.456662 getpid() = 2759
2759 20:25:19.456694 getgid() = 0
2759 20:25:19.456728 getuid() = 0
2759 20:25:19.456761 getegid() = 0
2759 20:25:19.456793 geteuid() = 0
2759 20:25:19.456828 geteuid() = 0
2759 20:25:19.456859 writev(4, [{iov_base="[2023/06/03
20:25:19.456612, 3,"..., iov_len=157}, {iov_base=" [nss_winbind (4418)]
Winbind e"..., iov_len=64}], 2) = 221
2759 20:25:19.456900 geteuid() = 0
2759 20:25:19.456932 writev(4, [{iov_base="", iov_len=0}, {iov_base="
Query username 'testuser'.\n", iov_len=24}], 2) = 24
2759 20:25:19.456974 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.457020 getpid() = 2759
2759 20:25:19.457058 getgid() = 0
2759 20:25:19.457091 getuid() = 0
2759 20:25:19.457125 getegid() = 0
2759 20:25:19.457157 geteuid() = 0
2759 20:25:19.457191 geteuid() = 0
2759 20:25:19.457224 writev(4, [{iov_base="[2023/06/03
20:25:19.456966, 5,"..., iov_len=149}, {iov_base=" WB command
lookupname start.\n", iov_len=31}], 2) = 180
2759 20:25:19.457264 geteuid() = 0
2759 20:25:19.457299 writev(4, [{iov_base="", iov_len=0}, {iov_base="
Search namespace 'SAMDOM' a"..., iov_len=70}], 2) = 70
2759 20:25:19.457361 fcntl(17, F_SETLKW, {l_type=F_RDLCK,
l_whence=SEEK_SET, l_start=2424, l_len=1}) = 0
2759 20:25:19.457405 fcntl(17, F_SETLKW, {l_type=F_UNLCK,
l_whence=SEEK_SET, l_start=2424, l_len=1}) = 0
2759 20:25:19.457442 fcntl(17, F_SETLKW, {l_type=F_RDLCK,
l_whence=SEEK_SET, l_start=8548, l_len=1}) = 0
2759 20:25:19.457478 fcntl(17, F_SETLKW, {l_type=F_UNLCK,
l_whence=SEEK_SET, l_start=8548, l_len=1}) = 0
2759 20:25:19.457515 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.457558 getpid() = 2759
2759 20:25:19.457591 getgid() = 0
2759 20:25:19.457624 getuid() = 0
2759 20:25:19.457656 getegid() = 0
2759 20:25:19.457689 geteuid() = 0
2759 20:25:19.457724 geteuid() = 0
2759 20:25:19.457756 writev(4, [{iov_base="[2023/06/03 20:25:19.457508,
10,"..., iov_len=158}, {iov_base=" wbint_bh_raw_call_send: Got op"...,
iov_len=70}], 2) = 228
2759 20:25:19.457808 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.457852 getpid() = 2759
2759 20:25:19.457885 getgid() = 0
2759 20:25:19.457917 getuid() = 0
2759 20:25:19.457949 getegid() = 0
2759 20:25:19.457981 geteuid() = 0
2759 20:25:19.458016 geteuid() = 0
2759 20:25:19.458048 writev(4, [{iov_base="[2023/06/03
20:25:19.457797, 5,"..., iov_len=150}, {iov_base=" WB command
lookupname end.\n", iov_len=29}], 2) = 179
2759 20:25:19.458088 geteuid() = 0
2759 20:25:19.458119 writev(4, [{iov_base="", iov_len=0}, {iov_base="
Found SID S-1-5-21-4190054395-"..., iov_len=76}], 2) = 76
2759 20:25:19.458158 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.458203 getpid() = 2759
2759 20:25:19.458236 getgid() = 0
2759 20:25:19.458269 getuid() = 0
2759 20:25:19.458301 getegid() = 0
2759 20:25:19.458334 geteuid() = 0
2759 20:25:19.458368 geteuid() = 0
2759 20:25:19.458401 writev(4, [{iov_base="[2023/06/03
20:25:19.458151, 5,"..., iov_len=145}, {iov_base=" WB command getpwsid
start.\n", iov_len=29}], 2) = 174
2759 20:25:19.458441 geteuid() = 0
2759 20:25:19.458474 writev(4, [{iov_base="", iov_len=0}, {iov_base="
Query user SID S-1-5-21-419005"..., iov_len=65}], 2) = 65
2759 20:25:19.458513 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.458556 getpid() = 2759
2759 20:25:19.458589 getgid() = 0
2759 20:25:19.458622 getuid() = 0
2759 20:25:19.458654 getegid() = 0
2759 20:25:19.458687 geteuid() = 0
2759 20:25:19.458721 geteuid() = 0
2759 20:25:19.458751 writev(4, [{iov_base="[2023/06/03
20:25:19.458506, 5,"..., iov_len=147}, {iov_base=" WB command
queryuser start.\n", iov_len=30}], 2) = 177
2759 20:25:19.458791 geteuid() = 0
2759 20:25:19.458824 writev(4, [{iov_base="", iov_len=0}, {iov_base="
Query user sid S-1-5-21-419005"..., iov_len=64}], 2) = 64
2759 20:25:19.458865 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.458907 getpid() = 2759
2759 20:25:19.458941 getgid() = 0
2759 20:25:19.458973 getuid() = 0
2759 20:25:19.459005 getegid() = 0
2759 20:25:19.459038 geteuid() = 0
2759 20:25:19.459073 geteuid() = 0
2759 20:25:19.459105 writev(4, [{iov_base="[2023/06/03 20:25:19.458857,
10,"..., iov_len=159}, {iov_base=" Convert the user SID S-1-5-21-"...,
iov_len=78}], 2) = 237
2759 20:25:19.459145 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.459186 getpid() = 2759
2759 20:25:19.459220 getgid() = 0
2759 20:25:19.459253 getuid() = 0
2759 20:25:19.459304 getegid() = 0
2759 20:25:19.459336 geteuid() = 0
2759 20:25:19.459370 geteuid() = 0
2759 20:25:19.459403 writev(4, [{iov_base="[2023/06/03
20:25:19.459137, 5,"..., iov_len=147}, {iov_base=" WB command
sids2xids start.\n", iov_len=30}], 2) = 177
2759 20:25:19.459443 geteuid() = 0
2759 20:25:19.459477 writev(4, [{iov_base="", iov_len=0}, {iov_base="
Resolving 1 SID(s).\n", iov_len=22}], 2) = 22
2759 20:25:19.459515 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.459558 getpid() = 2759
2759 20:25:19.459591 getgid() = 0
2759 20:25:19.459623 getuid() = 0
2759 20:25:19.459655 getegid() = 0
2759 20:25:19.459687 geteuid() = 0
2759 20:25:19.459721 geteuid() = 0
2759 20:25:19.459751 writev(4, [{iov_base="[2023/06/03 20:25:19.459507,
10,"..., iov_len=148}, {iov_base=" 0: SID S-1-5-21-4190054395-363"...,
iov_len=56}], 2) = 204
2759 20:25:19.459808 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.459854 getpid() = 2759
2759 20:25:19.459886 getgid() = 0
2759 20:25:19.459918 getuid() = 0
2759 20:25:19.459950 getegid() = 0
2759 20:25:19.459982 geteuid() = 0
2759 20:25:19.460015 geteuid() = 0
2759 20:25:19.460048 writev(4, [{iov_base="[2023/06/03 20:25:19.459796,
10,"..., iov_len=148}, {iov_base=" Found 1 (out of 1) SID(s) in c"...,
iov_len=38}], 2) = 186
2759 20:25:19.460090 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.460132 getpid() = 2759
2759 20:25:19.460165 getgid() = 0
2759 20:25:19.460197 getuid() = 0
2759 20:25:19.460229 getegid() = 0
2759 20:25:19.460261 geteuid() = 0
2759 20:25:19.460294 geteuid() = 0
2759 20:25:19.460328 writev(4, [{iov_base="[2023/06/03
20:25:19.460082, 5,"..., iov_len=148}, {iov_base=" WB command
sids2xids end.\n", iov_len=28}], 2) = 176
2759 20:25:19.460370 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.460412 getpid() = 2759
2759 20:25:19.460445 getgid() = 0
2759 20:25:19.460505 getuid() = 0
2759 20:25:19.460557 getegid() = 0
2759 20:25:19.460589 geteuid() = 0
2759 20:25:19.460623 geteuid() = 0
2759 20:25:19.460654 writev(4, [{iov_base="[2023/06/03
20:25:19.460362, 5,"..., iov_len=148}, {iov_base=" 0: Found XID 1004
for SID S-1-"..., iov_len=75}], 2) = 223
2759 20:25:19.460695 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.460738 getpid() = 2759
2759 20:25:19.460771 getgid() = 0
2759 20:25:19.460803 getuid() = 0
2759 20:25:19.460837 getegid() = 0
2759 20:25:19.460867 geteuid() = 0
2759 20:25:19.460902 geteuid() = 0
2759 20:25:19.460935 writev(4, [{iov_base="[2023/06/03 20:25:19.460687,
10,"..., iov_len=151}, {iov_base=" Received XID 1004 for SID S-1-"...,
iov_len=76}], 2) = 227
2759 20:25:19.460975 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.461015 getpid() = 2759
2759 20:25:19.461048 getgid() = 0
2759 20:25:19.461080 getuid() = 0
2759 20:25:19.461112 getegid() = 0
2759 20:25:19.461144 geteuid() = 0
2759 20:25:19.461179 geteuid() = 0
2759 20:25:19.461210 writev(4, [{iov_base="[2023/06/03 20:25:19.460967,
10,"..., iov_len=151}, {iov_base=" Preconfigured 'Domain Users' R"...,
iov_len=176}], 2) = 327
2759 20:25:19.461253 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.461297 getpid() = 2759
2759 20:25:19.461329 getgid() = 0
2759 20:25:19.461361 getuid() = 0
2759 20:25:19.461395 getegid() = 0
2759 20:25:19.461427 geteuid() = 0
2759 20:25:19.461461 geteuid() = 0
2759 20:25:19.461491 writev(4, [{iov_base="[2023/06/03 20:25:19.461245,
10,"..., iov_len=151}, {iov_base=" Setting 'homedir' to the templ"...,
iov_len=48}], 2) = 199
2759 20:25:19.461531 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.461574 getpid() = 2759
2759 20:25:19.461606 getgid() = 0
2759 20:25:19.461638 getuid() = 0
2759 20:25:19.461672 getegid() = 0
2759 20:25:19.461703 geteuid() = 0
2759 20:25:19.461737 geteuid() = 0
2759 20:25:19.461770 writev(4, [{iov_base="[2023/06/03 20:25:19.461523,
10,"..., iov_len=151}, {iov_base=" Setting 'shell' to the templat"...,
iov_len=47}], 2) = 198
2759 20:25:19.461811 fcntl(16, F_SETLKW, {l_type=F_RDLCK,
l_whence=SEEK_SET, l_start=212, l_len=1}) = 0
2759 20:25:19.461849 fcntl(16, F_SETLKW, {l_type=F_UNLCK,
l_whence=SEEK_SET, l_start=212, l_len=1}) = 0
2759 20:25:19.461904 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.461948 getpid() = 2759
2759 20:25:19.461982 getgid() = 0
2759 20:25:19.462013 getuid() = 0
2759 20:25:19.462046 getegid() = 0
2759 20:25:19.462078 geteuid() = 0
2759 20:25:19.462111 geteuid() = 0
2759 20:25:19.462144 writev(4, [{iov_base="[2023/06/03 20:25:19.461892,
10,"..., iov_len=151}, {iov_base=" Filling data received from net"...,
iov_len=47}], 2) = 198
2759 20:25:19.462186 geteuid() = 0
2759 20:25:19.462219 writev(4, [{iov_base="", iov_len=0},
{iov_base=" state->info: struct wbint_"..., iov_len=41}], 2) = 41
2759 20:25:19.462258 geteuid() = 0
2759 20:25:19.462290 writev(4, [{iov_base="", iov_len=0},
{iov_base=" domain_name "..., iov_len=39}], 2) = 39
2759 20:25:19.462330 geteuid() = 0
2759 20:25:19.462360 writev(4, [{iov_base="", iov_len=0},
{iov_base=" domain_name "..., iov_len=53}], 2) = 53
2759 20:25:19.462398 geteuid() = 0
2759 20:25:19.462431 writev(4, [{iov_base="", iov_len=0},
{iov_base=" acct_name "..., iov_len=39}], 2) = 39
2759 20:25:19.462476 geteuid() = 0
2759 20:25:19.462510 writev(4, [{iov_base="", iov_len=0},
{iov_base=" acct_name "..., iov_len=47}], 2) = 47
2759 20:25:19.462549 geteuid() = 0
2759 20:25:19.462581 writev(4, [{iov_base="", iov_len=0},
{iov_base=" full_name "..., iov_len=39}], 2) = 39
2759 20:25:19.462620 geteuid() = 0
2759 20:25:19.462653 writev(4, [{iov_base="", iov_len=0},
{iov_base=" full_name "..., iov_len=59}], 2) = 59
2759 20:25:19.462691 geteuid() = 0
2759 20:25:19.462724 writev(4, [{iov_base="", iov_len=0},
{iov_base=" homedir "..., iov_len=39}], 2) = 39
2759 20:25:19.462762 geteuid() = 0
2759 20:25:19.462795 writev(4, [{iov_base="", iov_len=0},
{iov_base=" homedir "..., iov_len=52}], 2) = 52
2759 20:25:19.462834 geteuid() = 0
2759 20:25:19.462866 writev(4, [{iov_base="", iov_len=0},
{iov_base=" shell "..., iov_len=39}], 2) = 39
2759 20:25:19.462905 geteuid() = 0
2759 20:25:19.462938 writev(4, [{iov_base="", iov_len=0},
{iov_base=" shell "..., iov_len=53}], 2) = 53
2759 20:25:19.462977 geteuid() = 0
2759 20:25:19.463009 writev(4, [{iov_base="", iov_len=0},
{iov_base=" uid "..., iov_len=63}], 2) = 63
2759 20:25:19.463048 geteuid() = 0
2759 20:25:19.463082 writev(4, [{iov_base="", iov_len=0},
{iov_base=" primary_gid "..., iov_len=69}], 2) = 69
2759 20:25:19.463120 geteuid() = 0
2759 20:25:19.463152 writev(4, [{iov_base="", iov_len=0},
{iov_base=" primary_group_name "..., iov_len=42}], 2) = 42
2759 20:25:19.463192 geteuid() = 0
2759 20:25:19.463223 writev(4, [{iov_base="", iov_len=0},
{iov_base=" user_sid "..., iov_len=84}], 2) = 84
2759 20:25:19.463262 geteuid() = 0
2759 20:25:19.463320 writev(4, [{iov_base="", iov_len=0},
{iov_base=" group_sid "..., iov_len=83}], 2) = 83
2759 20:25:19.463360 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2940, ...}) = 0
2759 20:25:19.463404 getpid() = 2759
2759 20:25:19.463436 getgid() = 0
2759 20:25:19.463468 getuid() = 0
2759 20:25:19.463500 getegid() = 0
2759 20:25:19.463531 geteuid() = 0
2759 20:25:19.463565 geteuid() = 0
2759 20:25:19.463598 writev(4, [{iov_base="[2023/06/03 20:25:19.463352,
10,"..., iov_len=151}, {iov_base=" Domain name is set, calling dc"...,
iov_len=61}], 2) = 212
2759 20:25:19.463651 epoll_wait(5, [], 1, 456) = 0
2759 20:25:19.920396 epoll_wait(5, <unfinished ...>
4418 20:25:24.459359 <... poll resumed>) = 0 (Timeout)
======= PREVIOUS OUTPUT LINE ===== poll([{fd=3, events=POLLIN|POLLHUP}],
1, 5000) = 0 (Timeout) =======
4418 20:25:24.459508 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000
<unfinished ...>
2759 20:25:24.923633 <... epoll_wait resumed>[], 1, 5000) = 0
So this is what winbind (the main process) is doing while my command
"hangs", Hopefully this gives a clue to somebody with more knowledge of
the winbind code than me :-)
- Kees.
More information about the samba
mailing list