Help needed: TCP Wizards (was 8.0-RC1 NFS client timeout issue)

Sun Nov 1 21:53:38 UTC 2009

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=<nop,nop,tstamp 2883094 1218858>
   2   0.00010 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Syn Seq=729399224 Len=0 Win=65535 Options=<mss 1460,nop,wscale 3,sackOK,tstamp 2883094 0>
   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=<nop,nop,tstamp 11852 2883094,mss 1460,nop,wscale 0,nop,nop,sackOK>
   5   0.00086 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=740 Ack=38857224 Seq=729399225 Len=0 Win=8326 Options=<nop,nop,tstamp 2883095 11852>
   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=<nop,nop,tstamp 11852 2883095>
   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=<nop,nop,tstamp 2883198 11853>
  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=<nop,nop,tstamp 47853 2883198>
  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=<nop,nop,tstamp 3242021 47853>
  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=<mss 1460,nop,wscale 3,sackOK,tstamp 3376760 0>
  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=<nop,nop,tstamp 61367 3376760,mss 1460,nop,wscale 0,nop,nop,sackOK>
  17 495.15040 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=871 Ack=159825644 Seq=369106878 Len=0 Win=8326 Options=<nop,nop,tstamp 3376761 61367>
  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=<mss 1460,nop,wscale 3,sackOK,tstamp 3376763 0>
  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=<nop,nop,tstamp 61367 3376763,mss 1460,nop,wscale 0,nop,nop,sackOK>
  23 495.15348 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=883 Ack=159964182 Seq=3875668539 Len=0 Win=8326 Options=<nop,nop,tstamp 3376764 61367>
  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=<nop,nop,tstamp 61367 3376764>
  27 495.15457 nfsv4-test.cis.uoguelph.ca -> nfsv4-solaris TCP D=2049 S=883 Rst Ack=159964182 Seq=3875668671 Len=0 Win=0