I have an issue where winbind will occasionally pause for 30 seconds.
# strace -T -t ls -l /share
16:52:20 read(4, "/var/lib/samba/winbindd_privileg"..., 35) = 35
<0.000009>
16:52:20 lstat("/var/lib/samba/winbindd_privileged",
{st_mode=S_IFDIR|0750, st_size=72, ...}) = 0 <0.000011>
16:52:20 lstat("/var/lib/samba/winbindd_privileged/pipe",
{st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 <0.000011>
16:52:20 socket(PF_FILE, SOCK_STREAM, 0) = 5 <0.000011>
16:52:20 fcntl(5, F_GETFL) = 0x2 (flags O_RDWR) <0.000006>
16:52:20 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000007>
16:52:20 fcntl(5, F_GETFD) = 0 <0.000006>
16:52:20 fcntl(5, F_SETFD, FD_CLOEXEC) = 0 <0.000006>
16:52:20 connect(5, {sa_family=AF_FILE,
path="/var/lib/samba/winbindd_privileged/pipe"}, 110) = 0
<0.000018>
16:52:20 close(4) = 0 <0.000011>
16:52:20 select(6, [5], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000007>
16:52:20 write(5,
"(\10\0\0\4\0\0\0d\20\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2088)
2088 <0.000011>
16:52:20 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout) <4.997279>
16:52:25 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout) <4.999895>
16:52:30 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout) <4.999885>
16:52:35 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout) <4.999914>
16:52:40 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout) <4.999891>
16:52:45 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout) <4.999916>
16:52:50 select(6, [5], NULL, NULL, {5, 0}) = 1 (in [5], left {4,
968000}) <0.033682>
16:52:50 read(5, "\354\f\0\0\2\0\0\0STARTREK-phx_api_release"...,
3240)
= 3240 <0.000014>
Notice the chain of select() calls between 16:52:20 and 16:52:50 that
all timeout after 5 seconds for a total of 30 seconds!
The winbind log has the following error when this occurs:
[2008/04/18 16:52:20, 3] libsmb/clikrb5.c:ads_krb5_mk_req(593)
ads_krb5_mk_req: krb5_cc_get_principal failed (No credentials cache
found)
[2008/04/18 16:52:50, 4] libsmb/clikrb5.c:ads_krb5_mk_req(610)
ads_krb5_mk_req: Advancing clock by 13 seconds to cope with clock skew
[2008/04/18 16:52:50, 3] libsmb/clikrb5.c:ads_cleanup_expired_creds(528)
ads_cleanup_expired_creds: Ticket in ccache[MEMORY:winbind_ccache]
expiration Fri, 18 Apr 2008 17:13:03 MST
The ads_krb5_mk_req function has a while loop that loops 3 times 'while
(!creds_ready && (i < maxtries))' (i=0, maxtries=3). This
corresponds
with 3 requests to the kdc for info during the period of the pause:
16:52:20.839894 IP 192.168.1.210.32891 > 192.168.1.207.88: v5
16:52:20.840419 IP 192.168.1.207.88 > 192.168.1.210.32891:
16:52:30.837599 IP 192.168.1.210.32891 > 192.168.1.207.88: v5
16:52:30.838482 IP 192.168.1.207.88 > 192.168.1.210.32891: v5
16:52:40.837652 IP 192.168.1.210.32891 > 192.168.1.207.88:
16:52:40.838606 IP 192.168.1.207.88 > 192.168.1.210.32891:
I don't understand why the select call appears to continue to block even
though the Samba machine (192.168.1.210) gets a response from the
Windows server (maybe I'm just interpreting the data wrong??).
I used 'net ads -U username keytab create to generate my keytab file (it
looks good as far as I can tell). 'net cache list' also reveals several
entries. Klist also shows a default principal entry. I'm not sure why it
can't find a credentials cache.
I've upgraded my krb5 from 1.4.3 to 1.6.2 without effect. Here's version
info:
Samba 3.0.28 (3.0.25a and 3.0.25c also had this problem)
Linux 2.6.16 (x64)
At this point I have no idea how to fix this problem. I've read more
samba how-to's than I thought possible and checked the relevant config
files. Everything is working ok except for this pause. I've upgraded the
relevant software but the problem persists.
Matt
Gerald (Jerry) Carter
2008-Apr-24 13:00 UTC
[Samba] select() timeout on winbindd_privileged pipe
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Humrick, Matt wrote:
| I have an issue where winbind will occasionally pause for 30 seconds.
|
| # strace -T -t ls -l /share
| 16:52:20 read(4, "/var/lib/samba/winbindd_privileg"..., 35) = 35
| <0.000009>
| 16:52:20 lstat("/var/lib/samba/winbindd_privileged",
You are tracing the client. But the log only shows the
parent winbindd process. I would check the child processes
because I'll bet you have more traffic that will
illuminate what is going on in those logs.
ls -l would do a lot of uid/gid -> SID translation and
LookupSid calls.
cheers, jerry
- --
====================================================================Samba
------- http://www.samba.org
Likewise Software --------- http://www.likewisesoftware.com
"What man is a man who does not make the world better?" --Balian
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.2.2 (Darwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org
iD8DBQFIEIRTIR7qMdg1EfYRApG4AKDpveWnszCQ/ou65g70GojhQG7U1gCgo1Rx
nt2iA5pKwSsMJjldkD4Y7VY=mxDI
-----END PGP SIGNATURE-----