[Samba] select() timeout on winbindd_privileged pipe

[Humrick, Matt]

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