Date: Tue, 25 Mar 2014 09:52:43 -0700 From: Kevin Oberman <rkoberman@gmail.com> To: Karl Pielorz <kpielorz_lst@tdx.co.uk> Cc: Marcelo Gondim <gondim@bsdinfo.com.br>, FreeBSD Stable Mailing List <freebsd-stable@freebsd.org> Subject: Re: sshd with zombie process on FreeBSD 10.0-STABLE - workaround Message-ID: <CAN6yY1sNiF7m%2BSRcgHWWQY0M38oGkWrovkjZwicbidoZb2f%2Bmw@mail.gmail.com> In-Reply-To: <7419ED158F7CE99854773527@Mail-PC.tdx.co.uk> References: <53016D97.5030909@bsdinfo.com.br> <CAN6yY1uucfkdXxkCF30w1Q9vffRpDLxM90Sz1XVbdn5W69vQMg@mail.gmail.com> <5329D81E.7040709@bsdinfo.com.br> <201403201058.38555.jhb@freebsd.org> <532B7DEC.7010809@bsdinfo.com.br> <CAN6yY1sf0z_jBJgBy2dZX0a3JJnyTnq76_DepXzG32GWgHHO6A@mail.gmail.com> <7419ED158F7CE99854773527@Mail-PC.tdx.co.uk>
next in thread | previous in thread | raw e-mail | index | archive | help
On Tue, Mar 25, 2014 at 3:52 AM, Karl Pielorz <kpielorz_lst@tdx.co.uk>wrote: > > > --On 21 March 2014 22:02 -0700 Kevin Oberman <rkoberman@gmail.com> wrote: > > Ideally I'd look to try and capture the packets st the end of the session. >> Can you do something to trigger this reliably? if so "standard" "tcpdump >> -pw file.bpf host HOST". I seem to recall that these connections are >> scheduled. If so, you can put the packet capture in a crontab to run at >> the same time. If you feed this to a tool like wireshark, you should get >> a good idea of what is happening, if not why. I understand that the >> timing of this might be very tricky. >> > > Ok, fwiw as I have this issue as well - I've done a packet capture (it's > below). This box has 59 'CLOSED' sockets from ssh on it, and 60 sshd stuck. > > Also - initially I thought this was a Xen issue - so there's a couple of > posts on that list from a couple of weeks ago, in brief - the sshd > processes I have are stuck in 'urdlck' - one of the Xen guys commented "It > seems like the process is stuck while trying to acquire a rw mutex in read > mode." > > I did a backtrace of a stuck process - I can post that if you want (or > check the FreeBSD-Xen list for 'stuck sshd in urdlck'. > > Also, if I ssh into this host, 90% of the time (seems to get worse the > longer the box is up) I get: > > " > ssh_exchange_identification: Connection closed by remote host > " > > That does not leave a lingering CLOSED socket. In fact, a successful ssh > login - and logout, does not in testing appear to leave a lingering CLOSED > socket, nor sshd stuck in urdlck - so I'm not entirely sure where they're > coming from, or how often they are created. > > tcpdump from the start of a successful ssh connect: > > 10:47:04.777765 IP (tos 0x0, ttl 61, id 4058, offset 0, flags [DF], proto > TCP (6), length 60) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [S], cksum 0x57ce > (correct), seq 634709832, win 65535, options [mss 1368,nop,wscale > 3,sackOK,TS val 1019391535 ecr 0], length 0 > > 10:47:04.777776 IP (tos 0x0, ttl 64, id 10060, offset 0, flags [DF], proto > TCP (6), length 60) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [S.], cksum 0x7ef8 > (incorrect -> 0x69d8), seq 2316386788, ack 634709833, win 65535, options > [mss 1368,nop,wscale 6,sackOK,TS val 805368299 ecr 1019391535], length 0 > > 10:47:04.804218 IP (tos 0x0, ttl 61, id 4059, offset 0, flags [DF], proto > TCP (6), length 52) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [.], cksum 0x77d3 > (correct), ack 1, win 8305, options [nop,nop,TS val 1019391538 ecr > 805368299], length 0 > > 10:47:04.809692 IP (tos 0x0, ttl 64, id 10061, offset 0, flags [DF], proto > TCP (6), length 99) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [P.], cksum 0x7f1f > (incorrect -> 0x5799), seq 1:48, ack 1, win 1038, options [nop,nop,TS val > 805368328 ecr 1019391538], length 47 > > 10:47:04.836110 IP (tos 0x0, ttl 61, id 4060, offset 0, flags [DF], proto > TCP (6), length 92) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [P.], cksum 0x8afa > (correct), seq 1:41, ack 48, win 8305, options [nop,nop,TS val 1019391541 > ecr 805368328], length 40 > > 10:47:04.836669 IP (tos 0x0, ttl 64, id 10062, offset 0, flags [DF], proto > TCP (6), length 1596) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [P.], cksum 0x84f8 > (incorrect -> 0x4d42), seq 48:1592, ack 41, win 1038, options [nop,nop,TS > val 805368358 ecr 1019391541], length 1544 > > > And the end of the session: > > 10:47:15.243540 IP (tos 0x10, ttl 61, id 4132, offset 0, flags [DF], proto > TCP (6), length 100) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [P.], cksum 0x6364 > (correct), seq 2321:2369, ack 3520, win 8305, options [nop,nop,TS val > 1019392582 ecr 805375068], length 48 > > 10:47:15.243736 IP (tos 0x10, ttl 64, id 10125, offset 0, flags [DF], > proto TCP (6), length 100) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [P.], cksum 0x7f20 > (incorrect -> 0x3ea8), seq 3520:3568, ack 2369, win 1038, options > [nop,nop,TS val 805378765 ecr 1019392582], length 48 > > 10:47:15.243796 IP (tos 0x10, ttl 64, id 10126, offset 0, flags [DF], > proto TCP (6), length 100) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [P.], cksum 0x7f20 > (incorrect -> 0xdd22), seq 3568:3616, ack 2369, win 1038, options > [nop,nop,TS val 805378765 ecr 1019392582], length 48 > > 10:47:15.244627 IP (tos 0x10, ttl 64, id 10127, offset 0, flags [DF], > proto TCP (6), length 84) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [P.], cksum 0x7f10 > (incorrect -> 0x86ed), seq 3616:3648, ack 2369, win 1038, options > [nop,nop,TS val 805378765 ecr 1019392582], length 32 > > 10:47:15.244812 IP (tos 0x10, ttl 64, id 10128, offset 0, flags [DF], > proto TCP (6), length 212) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [P.], cksum 0x7f90 > (incorrect -> 0x431c), seq 3648:3808, ack 2369, win 1038, options > [nop,nop,TS val 805378765 ecr 1019392582], length 160 > > 10:47:15.271439 IP (tos 0x10, ttl 61, id 4134, offset 0, flags [DF], proto > TCP (6), length 52) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [.], cksum 0x3381 > (correct), ack 3616, win 8299, options [nop,nop,TS val 1019392585 ecr > 805378765], length 0 > > 10:47:15.272238 IP (tos 0x10, ttl 61, id 4135, offset 0, flags [DF], proto > TCP (6), length 52) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [.], cksum 0x32d9 > (correct), ack 3808, win 8275, options [nop,nop,TS val 1019392585 ecr > 805378765], length 0 > > 10:47:15.273515 IP (tos 0x10, ttl 61, id 4137, offset 0, flags [DF], proto > TCP (6), length 84) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [P.], cksum 0x43cc > (correct), seq 2369:2401, ack 3808, win 8305, options [nop,nop,TS val > 1019392585 ecr 805378765], length 32 > > 10:47:15.276199 IP (tos 0x10, ttl 61, id 4138, offset 0, flags [DF], proto > TCP (6), length 116) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [P.], cksum 0xb169 > (correct), seq 2401:2465, ack 3808, win 8305, options [nop,nop,TS val > 1019392585 ecr 805378765], length 64 > > 10:47:15.276220 IP (tos 0x10, ttl 64, id 10129, offset 0, flags [DF], > proto TCP (6), length 52) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [.], cksum 0x7ef0 > (incorrect -> 0x4ea3), ack 2465, win 1037, options [nop,nop,TS val > 805378793 ecr 1019392585], length 0 > > 10:47:15.276970 IP (tos 0x10, ttl 61, id 4140, offset 0, flags [DF], proto > TCP (6), length 52) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [F.], cksum 0x325a > (correct), seq 2465, ack 3808, win 8305, options [nop,nop,TS val 1019392585 > ecr 805378765], length 0 > > 10:47:15.276978 IP (tos 0x10, ttl 64, id 10130, offset 0, flags [DF], > proto TCP (6), length 52) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [.], cksum 0x7ef0 > (incorrect -> 0x4e9c), ack 2466, win 1038, options [nop,nop,TS val > 805378798 ecr 1019392585], length 0 > > 10:47:15.277212 IP (tos 0x10, ttl 64, id 10131, offset 0, flags [DF], > proto TCP (6), length 52) > 192.168.0.138.22 > 192.168.0.37.31139: Flags [F.], cksum 0x7ef0 > (incorrect -> 0x4e9b), seq 3808, ack 2466, win 1038, options [nop,nop,TS > val 805378798 ecr 1019392585], length 0 > > 10:47:15.303993 IP (tos 0x10, ttl 61, id 4142, offset 0, flags [DF], proto > TCP (6), length 52) > 192.168.0.37.31139 > 192.168.0.138.22: Flags [.], cksum 0x3235 > (correct), ack 3809, win 8305, options [nop,nop,TS val 1019392588 ecr > 805378798], length 0 > > > This box has no services running on it at present, and just sits there > idle. I'll periodically check on it and see if the CLOSED socket count, or > hung sshd count goes up. > > It's runing as a PVHVM domU under XenServer 6.2 > Since I am retired, I no longer have access to my beloved "TCP/IP Illustrated Vol. 1", but I believe CLOSED status indicates that the socket is no longer in use.As the name says, it is CLOSED. I don't know why sshd should be waiting on a CLOSED socket, nor do I understand why a CLOSED server socket should live on for extended times. That said, I have been monitoring my FreeBSD 10 system and it seems to pick up an occasional case where a socket gets "stuck" in the CLOSED state for a very long time. I can't say forever, but at least many minutes. I don't see this on 9.2 systems. Right now I have two CLOSED sockets, both the the same address on port 80. It appears that the only thing that removes the socket is to kill the owning process (in this case it's Firefox). The owning firefox process does exist just fine when asked and I think sshd should do so as well, but it looks to me like the root problem is that CLOSED socket seem to live on in 10.0 and they don't on older versions. I think it's time to move this over to net@, as I suspect a change made in 10 is triggering this. I'm not sure the changes is wrong or that sshd is wrong in not exiting cleanly when sockets are hanging around in CLOSED state. (Nor am I sure sshd is wrong.) If I am confused about this, please let me know. I'm going ot read the 10.0 release notes to see if they say anything about this. -- R. Kevin Oberman, Network Engineer, Retired E-mail: rkoberman@gmail.com
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAN6yY1sNiF7m%2BSRcgHWWQY0M38oGkWrovkjZwicbidoZb2f%2Bmw>