wierd NFS problem (was: LOR in -current NFS client code + possible patch)

On 21 Apr, To: current_at_freebsd.org wrote:
> I had something wedge up in the NFS client code in a recent version of
> -current.
> 	5.0-CURRENT #61: Sat Apr 19 00:36:17 PDT 2003
> 
> I got the console message:
> 
> Apr 21 20:52:07 scratch kernel: nfs server mousie:/home: not responding
> 
> TCP connections continued to work, and another client was still able to
> access the server, so the problem was definitely in the client code.
> 
> When I attempted to kill the process that seemed to be responsible for
> wedging NFS, I got a lock order reversal message:
> 
> Apr 21 20:54:33 scratch kernel: lock order reversal
> Apr 21 20:54:33 scratch kernel: 1st 0xc893ab68 vnode interlock (vnode interlock)
>  _at_ /usr/src/sys/nfsclient/nfs_vnops.c:2792
> Apr 21 20:54:33 scratch kernel: 2nd 0xc69f4248 process lock (process lock) _at_ /us
> r/src/sys/nfsclient/nfs_socket.c:1239
> Apr 21 20:54:33 scratch kernel: Stack backtrace:


> I don't know what caused the original problem, but the lock order
> reversal is caused by nfs_flush() calling nfs_sigintr() while holding a
> vnode interlock, and nfs_sigintr() calls PROC_LOCK().
> 
> It looks to me like the following patch is the proper fix. There is
> another call to nfs_sigintr() in nfs_flush(), but it looks like
> BUF_TIMELOCK() must release the interlock in the error case.  Comments?

[ patch deleted ]

I just tested the patch and it seems to solve the lock order reversal
problem and it allows the wedged process to be killed.

One interesting bit of data is that once the offending process is gone,
the NFS mount point unwedges.

Even more interesting is what I observed on the server using tcpdump
while the process was hung:

# tcpdump -n -s 1500 not tcp
tcpdump: listening on fxp0
03:45:30.405336 192.168.101.3.1105920791 > 192.168.101.2.2049: 1472 write fh 959,593683/187071 6005 bytes _at_ 0x000000000 (frag 41311:1480_at_0+)
03:45:30.405443 192.168.101.3 > 192.168.101.2: udp (frag 41311:1480_at_1480+)
03:45:30.405566 192.168.101.3 > 192.168.101.2: udp (frag 41311:1480_at_2960+)
03:45:30.405691 192.168.101.3 > 192.168.101.2: udp (frag 41311:1480_at_4440+)
03:45:30.405710 truncated-ip - 2 bytes missing! 192.168.101.3 > 192.168.101.2: udp (frag 41311:224_at_5920)

I saw this packet sequence repeated about every 16 seconds.  As this was
happening the ip "fragments dropped after timeout counter" in
"netstat -s" was incrementing.

After the offending process had been killed, NFS writes looked normal,
without the "truncated-ip" message from tcpdump.