From owner-freebsd-current@FreeBSD.ORG Sun Nov 1 21:53:38 2009 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id D6B36106566B; Sun, 1 Nov 2009 21:53:38 +0000 (UTC) (envelope-from rmacklem@uoguelph.ca) Received: from esa-annu.mail.uoguelph.ca (esa-annu.mail.uoguelph.ca [131.104.91.36]) by mx1.freebsd.org (Postfix) with ESMTP id 6921B8FC08; Sun, 1 Nov 2009 21:53:37 +0000 (UTC) X-IronPort-Anti-Spam-Filtered: true X-IronPort-Anti-Spam-Result: AuMFAFGS7UqDaFvJ/2dsb2JhbACQIQHHXoQ5BIFi X-IronPort-AV: E=Sophos;i="4.44,662,1249272000"; d="scan'208";a="52030966" Received: from ganges.cs.uoguelph.ca ([131.104.91.201]) by esa-annu-pri.mail.uoguelph.ca with ESMTP; 01 Nov 2009 16:53:37 -0500 Received: from localhost (localhost.localdomain [127.0.0.1]) by ganges.cs.uoguelph.ca (Postfix) with ESMTP id 3FBFEFB8027; Sun, 1 Nov 2009 16:53:37 -0500 (EST) X-Virus-Scanned: amavisd-new at ganges.cs.uoguelph.ca Received: from ganges.cs.uoguelph.ca ([127.0.0.1]) by localhost (ganges.cs.uoguelph.ca [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id vC3WPGoW-n0R; Sun, 1 Nov 2009 16:53:35 -0500 (EST) Received: from muncher.cs.uoguelph.ca (muncher.cs.uoguelph.ca [131.104.91.102]) by ganges.cs.uoguelph.ca (Postfix) with ESMTP id 82C6FFB801F; Sun, 1 Nov 2009 16:53:35 -0500 (EST) Received: from localhost (rmacklem@localhost) by muncher.cs.uoguelph.ca (8.11.7p3+Sun/8.11.6) with ESMTP id nA1M0n523077; Sun, 1 Nov 2009 17:00:49 -0500 (EST) X-Authentication-Warning: muncher.cs.uoguelph.ca: rmacklem owned process doing -bs Date: Sun, 1 Nov 2009 17:00:49 -0500 (EST) From: Rick Macklem X-X-Sender: rmacklem@muncher.cs.uoguelph.ca To: freebsd-current@freebsd.org Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed Cc: dfr@freebsd.org, O.Seibert@cs.ru.nl Subject: Help needed: TCP Wizards (was 8.0-RC1 NFS client timeout issue) X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 01 Nov 2009 21:53:38 -0000 I can now reproduce what I think others were seeing as slow reconnects when using NFSv3 over TCP against a server that disconnects inactive TCP connections. I have had some luck figuring out what is going on and can reproduce it fairly easily, but I really need help from someone who understands the FreeBSD TCP stack. Here's what happens when things break: - the krpc client does a reconnect like normal and the 3 way handshake works for the new socket. - the client sends an RPC on the new socket - at about the same time as this data send, the FreeBSD client sends a reset (yes, that's correct, an RST). --> not surprisingly, the server closes down the new connection and things get stuck until a timeout and another reconnect get things going again. This can be seen by the snoop trace that follows, with the RST at packet #18. (If there isn't a client->server RST packet generated by FreeBSD, the new connection works fine.) What do I know about this from printfs in the code: - It seems to happen when the new socket is at the same address as the old one. (Not a bug. Just happens that uma_zalloc() allocates the same memory as the old one that has been soclose()'d.) - It is timing related. If I add too many printfs, I can't reproduce the problem. My TCP is really rusty, but my theory is that some timer has been set by the FIN sent from the server for the old socket and it is still working on sending the RST when, somehow, the new socket and its tcp pcb get used for the send? Anyone out there able to help? (Please, please..) Here's a snoop trace of one of these (sorry about the long lines). You can see a successful reconnect, a Fin from the server disconnecting after 360sec and then the new connection being created with port#871. Then, at packet #18, there's that pesky RST!! --- snoop trace of FreeBSD-current client nfsv4-test mounted against a Solaris10 server called nfsv4-solaris. (The mount is the regular client, although that shouldn't matter, using NFSv3 over TCP.) 1 0.00000 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=864 Fin Ack=2981056244 Seq=3573648276 Len=0 Win=16588 Options= 2 0.00010 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Syn Seq=729399224 Len=0 Win=65535 Options= 3 0.00054 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=864 S=2049 Rst Seq=2981056244 Len=0 Win=0 4 0.00055 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=740 S=2049 Syn Ack=729399225 Seq=38857223 Len=0 Win=49232 Options= 5 0.00086 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Ack=38857224 Seq=729399225 Len=0 Win=8326 Options= 6 0.00104 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris NFS C FSSTAT3 FH=9D01 7 0.00180 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=740 S=2049 Ack=729399357 Seq=38857224 Len=0 Win=49100 Options= 8 0.00295 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca NFS R FSSTAT3 OK 9 0.10350 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Ack=38857396 Seq=729399357 Len=0 Win=16588 Options= 10 360.00514 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=740 S=2049 Fin Ack=729399357 Seq=38857396 Len=0 Win=49232 Options= 11 360.00549 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Rst Ack=38857397 Seq=729399357 Len=0 Win=0 12 360.00557 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Rst Ack=38857397 Seq=729399357 Len=0 Win=0 13 360.00586 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Ack=38857397 Seq=729399357 Len=0 Win=16588 Options= 14 360.00594 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=740 S=2049 Rst Seq=38857397 Len=0 Win=0 15 495.15000 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=871 Syn Seq=369106877 Len=0 Win=65535 Options= 16 495.15013 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=871 S=2049 Syn Ack=369106878 Seq=159825643 Len=0 Win=49232 Options= 17 495.15040 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=871 Ack=159825644 Seq=369106878 Len=0 Win=8326 Options= 18 495.15089 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=871 Rst Ack=159825644 Seq=369106878 Len=0 Win=0 19 495.15162 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris NFS C FSSTAT3 FH=9D01 20 495.15265 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=871 S=2049 Rst Seq=159825644 Len=0 Win=0 21 495.15305 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=883 Syn Seq=3875668538 Len=0 Win=65535 Options= 22 495.15322 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=883 S=2049 Syn Ack=3875668539 Seq=159964181 Len=0 Win=49232 Options= 23 495.15348 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=883 Ack=159964182 Seq=3875668539 Len=0 Win=8326 Options= 24 495.15368 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris NFS C FSSTAT3 FH=9D01 25 495.15374 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=883 Rst Ack=159964182 Seq=3875668539 Len=0 Win=0 26 495.15427 nfsv4-solaris -> nfsv4-test.cis.uoguelph.ca TCP D=883 S=2049 Ack=3875668671 Seq=159964182 Len=0 Win=49100 Options= 27 495.15457 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=883 Rst Ack=159964182 Seq=3875668671 Len=0 Win=0