[Samba] 35 second wait when cache expired
John Dunbar
john.dunbar1863 at gmail.com
Fri May 2 10:19:04 MDT 2014
Hello,
So my problem was that the firewall kills idle sessions after 1 minute.
Next question, is there a way to make winbind send keepalives down session
started by the epmap request?
So on mine, the quick epmap to port 135 was fine, port 49155 was assigned,
that was used once then the firewall idle timeout would kill it after a
minute. The next time winbind went to use it it was gone and (after 35
seconds of retrying) it would create another.
I need a way to keep that 49155 session alive, or I'd need to set huge
timeouts on the firewall to cover whatever the longest idle session I
expect to be.
I've seen keepalive = X option and also socket options = SO_KEEPALIVE for
smb.conf but neither do exactly what I need.
How does everyone else handle this when company policy means we need an
idle timeout?
Thanks!
On Tue, Apr 22, 2014 at 2:20 PM, John Dunbar <john.dunbar1863 at gmail.com>wrote:
> 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