[Samba] 35 second wait when cache expired
John Dunbar
john.dunbar1863 at gmail.com
Tue Apr 22 07:20:39 MDT 2014
Hello,
I've got an issue with RHEL6 running smbd & winbindd version
3.6.9-168.el6_5. This is authenticating against a Windows 2008R2 domain
using the rid backend.
If I run any command that has to look up user info I get a 35 second delay,
after this initial delay it's fine until the cache time-out, then it
happens again.
This is making logins and most commands hang for 35 seconds before
returning.
For example, I ran 'strace ps aux' at 22:22:55, it doesn't return until
22:23:30
The 35 seconds delay happens where the timeouts are listed here:
connect(3, {sa_family=AF_FILE, path="/var/run/winbindd/pipe"}, 110) = 0
poll([{fd=3, events=POLLIN|POLLHUP}], 1, 0) = 0 (Timeout)
write(3, "0\10\0\0\0\0\0\0\0\0\0\0 at +\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
2096) = 2096
poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3,
revents=POLLIN}])
read(3,
"\250\r\0\0\2\0\0\0\33\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
3496) = 3496
poll([{fd=3, events=POLLIN|POLLHUP}], 1, 0) = 0 (Timeout)
write(3, "0\10\0\0/\0\0\0\0\0\0\0 at +\0\0\0\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
2096) = 2096
poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3,
revents=POLLIN}])
read(3,
"\313\r\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\0"...,
3496) = 3496
poll([{fd=3, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=3,
revents=POLLIN}])
read(3, "/var/lib/samba/winbindd_privileg"..., 35) = 35
lstat("/var/lib/samba/winbindd_privileged", {st_mode=S_IFDIR|0750,
st_size=4096, ...}) = 0
lstat("/var/lib/samba/winbindd_privileged/pipe", {st_mode=S_IFSOCK|0777,
st_size=0, ...}) = 0
socket(PF_FILE, SOCK_STREAM, 0) = 4
fcntl(4, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
fcntl(4, F_GETFD) = 0
fcntl(4, F_SETFD, FD_CLOEXEC) = 0
connect(4, {sa_family=AF_FILE,
path="/var/lib/samba/winbindd_privileged/pipe"}, 110) = 0
close(3) = 0
poll([{fd=4, events=POLLIN|POLLHUP}], 1, 0) = 0 (Timeout)
write(4, "0\10\0\0\1\0\0\0\0\0\0\0 at +\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
2096) = 2096
poll([{fd=4, events=POLLIN|POLLHUP}], 1, 5000) = 0 (Timeout)
poll([{fd=4, events=POLLIN|POLLHUP}], 1, 5000) = 0 (Timeout)
poll([{fd=4, events=POLLIN|POLLHUP}], 1, 5000) = 0 (Timeout)
poll([{fd=4, events=POLLIN|POLLHUP}], 1, 5000) = 0 (Timeout)
poll([{fd=4, events=POLLIN|POLLHUP}], 1, 5000) = 0 (Timeout)
poll([{fd=4, events=POLLIN|POLLHUP}], 1, 5000) = 1 ([{fd=4,
revents=POLLIN}])
read(4,
"\250\r\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\0\0\0\0"...,
3496) = 3496
open("/proc/self/stat", O_RDONLY) = 3
read(3, "11072 (ps) R 11071 11071 28516 3"..., 1023) = 221
close(3) = 0
ioctl(1, TIOCGWINSZ, 0x7fff1f7dc340) = -1 ENOTTY (Inappropriate ioctl
for device)
I have a tcpdump running in another window that captures it: (172.22.1.42
is my host, 172.23.144.4 is the Domain controller)
22:22:55.352972 IP 172.22.1.42.38628 > 172.23.144.4.389: Flags [P.], seq
2791860238:2791860369, ack 2839412772, win 123, options [nop,nop,TS val
579759962 ecr 3024574255
], length 131
22:22:55.353875 IP 172.23.144.4.389 > 172.22.1.42.38628: Flags [P.], seq
1:88, ack 131, win 513, options [nop,nop,TS val 3024629014 ecr 579759962],
length 87
22:22:55.353893 IP 172.22.1.42.38628 > 172.23.144.4.389: Flags [.], ack 88,
win 123, options [nop,nop,TS val 579759963 ecr 3024629014], length 0
22:22:55.356508 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
2793732693:2793732845, ack 1998292199, win 131, options [nop,nop,TS val
579759965 ecr 30245777
62], length 152
22:22:55.558720 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
0:152, ack 1, win 131, options [nop,nop,TS val 579760168 ecr 3024577762],
length 152
22:22:55.964734 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
0:152, ack 1, win 131, options [nop,nop,TS val 579760574 ecr 3024577762],
length 152
22:22:56.776799 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
0:152, ack 1, win 131, options [nop,nop,TS val 579761386 ecr 3024577762],
length 152
22:22:58.400646 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
0:152, ack 1, win 131, options [nop,nop,TS val 579763010 ecr 3024577762],
length 152
22:23:01.648677 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
0:152, ack 1, win 131, options [nop,nop,TS val 579766258 ecr 3024577762],
length 152
22:23:01.802208 IP 172.23.144.4.445 > 172.22.1.42.56585: Flags [.], seq
1509087978:1509087979, ack 3025959720, win 509, length 1[|SMB]
22:23:01.802223 IP 172.22.1.42.56585 > 172.23.144.4.445: Flags [.], ack 1,
win 165, options [nop,nop,TS val 579766411 ecr 3024557653,nop,nop,sack 1
{0:1}], length 0
22:23:04.948114 IP 172.23.144.4.445 > 172.22.1.42.56593: Flags [.], seq
3884283286:3884283287, ack 540995472, win 509, length 1[|SMB]
22:23:04.948130 IP 172.22.1.42.56593 > 172.23.144.4.445: Flags [.], ack 1,
win 190, options [nop,nop,TS val 579769557 ecr 3024557967,nop,nop,sack 1
{0:1}], length 0
22:23:08.144695 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
0:152, ack 1, win 131, options [nop,nop,TS val 579772754 ecr 3024577762],
length 152
22:23:21.136680 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [P.], seq
0:152, ack 1, win 131, options [nop,nop,TS val 579785746 ecr 3024577762],
length 152
22:23:30.390871 IP 172.22.1.42.59600 > 172.23.144.4.49155: Flags [F.], seq
152, ack 1, win 131, options [nop,nop,TS val 579795000 ecr 3024577762],
length 0
22:23:30.406506 IP 172.22.1.42.54400 > 172.23.144.4.53: 11140+ A?
XXXX.Blah.local. (48) **EDITED TO HIDE REAL NAME**
22:23:30.407946 IP 172.23.144.4.53 > 172.22.1.42.54400: 11140* 1/0/0 A
172.23.144.4 (64)
22:23:30.408033 IP 172.22.1.42.55891 > 172.23.144.4.53: 38676+ AAAA?
XXXX.Blah.local. (48) **EDITED TO HIDE REAL NAME**
22:23:30.408842 IP 172.23.144.4.53 > 172.22.1.42.55891: 38676* 0/1/0 (95)
22:23:30.409439 IP 172.22.1.42.53732 > 172.23.144.4.135: Flags [S], seq
2711114410, win 14600, options [mss 1460,sackOK,TS val 579795018 ecr
0,nop,wscale 7], length 0
22:23:30.410081 IP 172.23.144.4.135 > 172.22.1.42.53732: Flags [S.], seq
589124558, ack 2711114411, win 8192, options [mss 1460,nop,nop,sackOK],
length 0
22:23:30.410114 IP 172.22.1.42.53732 > 172.23.144.4.135: Flags [.], ack 1,
win 14600, length 0
22:23:30.411829 IP 172.22.1.42.53732 > 172.23.144.4.135: Flags [P.], seq
1:73, ack 1, win 14600, length 72
22:23:30.412119 IP 172.23.144.4.135 > 172.22.1.42.53732: Flags [.], ack 73,
win 65463, length 0
22:23:30.412505 IP 172.23.144.4.135 > 172.22.1.42.53732: Flags [P.], seq
1:61, ack 73, win 65463, length 60
22:23:30.412517 IP 172.22.1.42.53732 > 172.23.144.4.135: Flags [.], ack 61,
win 14600, length 0
22:23:30.416062 IP 172.22.1.42.53732 > 172.23.144.4.135: Flags [P.], seq
73:229, ack 61, win 14600, length 156
22:23:30.416337 IP 172.23.144.4.135 > 172.22.1.42.53732: Flags [.], ack
229, win 65379, length 0
22:23:30.416741 IP 172.23.144.4.135 > 172.22.1.42.53732: Flags [P.], seq
61:213, ack 229, win 65379, length 152
22:23:30.420016 IP 172.22.1.42.53732 > 172.23.144.4.135: Flags [F.], seq
229, ack 213, win 15544, length 0
22:23:30.480817 IP 172.22.1.42.59633 > 172.23.144.4.49155: Flags [.], ack
4154531756, win 131, options [nop,nop,TS val 579795090 ecr 3024632523],
length 0
I don't understand why winbind keeps trying a high port for that initial
period, then drops back to another endpoint mapper request then finally
kicks into life.
Is there any configuration I can change to stop the hold up/retries?
I have winbindd debug up to 10 (they've turned over since I ran that but
here's an example from log.winbindd starting at 22:47:22 just before the 35
second pause):
[2014/04/22 22:47:22.666663, 6] winbindd/winbindd.c:822(new_connection)
accepted socket 32
[2014/04/22 22:47:22.666976, 10] winbindd/winbindd.c:672(process_request)
process_request: request fn INTERFACE_VERSION
[2014/04/22 22:47:22.667053, 3]
winbindd/winbindd_misc.c:384(winbindd_interface_version)
[11542]: request interface version
[2014/04/22 22:47:22.667142, 10]
winbindd/winbindd.c:768(winbind_client_response_written)
winbind_client_response_written[11542:INTERFACE_VERSION]: delivered
response to client
[2014/04/22 22:47:22.667281, 10] winbindd/winbindd.c:672(process_request)
process_request: request fn WINBINDD_PRIV_PIPE_DIR
[2014/04/22 22:47:22.667348, 3]
winbindd/winbindd_misc.c:417(winbindd_priv_pipe_dir)
[11542]: request location of privileged pipe
[2014/04/22 22:47:22.667448, 10]
winbindd/winbindd.c:768(winbind_client_response_written)
winbind_client_response_written[11542:WINBINDD_PRIV_PIPE_DIR]: delivered
response to client
[2014/04/22 22:47:22.667605, 6] winbindd/winbindd.c:822(new_connection)
accepted socket 33
[2014/04/22 22:47:22.667724, 6]
winbindd/winbindd.c:870(winbind_client_request_read)
closing socket 32, client exited
[2014/04/22 22:47:22.667900, 10] winbindd/winbindd.c:645(process_request)
process_request: Handling async request 11542:GETPWNAM
[2014/04/22 22:47:22.667976, 3]
winbindd/winbindd_getpwnam.c:56(winbindd_getpwnam_send)
getpwnam x
[2014/04/22 22:47:22.668051, 1]
../librpc/ndr/ndr.c:284(ndr_print_function_debug)
wbint_LookupName: struct wbint_LookupName
in: struct wbint_LookupName
domain : *
domain : 'BLAH' **EDITED**
name : *
name : 'X'
flags : 0x00000008 (8)
[2014/04/22 22:47:22.668297, 10]
winbindd/winbindd_cache.c:4915(wcache_fetch_ndr)
Entry has wrong sequence number: 4017751
[2014/04/22 22:47:57.704660, 6] winbindd/winbindd.c:822(new_connection)
accepted socket 32
[2014/04/22 22:47:57.704908, 10] winbindd/winbindd.c:672(process_request)
process_request: request fn INTERFACE_VERSION
[2014/04/22 22:47:57.704981, 3]
winbindd/winbindd_misc.c:384(winbindd_interface_version)
[11542]: request interface version
[2014/04/22 22:47:57.705070, 10]
winbindd/winbindd.c:768(winbind_client_response_written)
winbind_client_response_written[11542:INTERFACE_VERSION]: delivered
response to client
[2014/04/22 22:47:57.705196, 10] winbindd/winbindd.c:672(process_request)
process_request: request fn WINBINDD_PRIV_PIPE_DIR
Hopefully that's not either too much or too little info!
Any ideas or pointers in the right direction would be appreciated.
More information about the samba
mailing list