Re: [NFS] NFS rpc and stale handles on 2.6.x servers

[Roman Kagan <Roman.Kagan@itep.ru>]

On Fri, Jan 30, 2004 at 10:16:05AM +0000, Neil Brown wrote:
> The "RPC request reserved 0 ..." is very odd. It does immediately
> indicate a major problem, but it should be fixed, if only I could
> figure out what was causing it.

In case it helps: having enabled svcsock debugging by

  echo $[0x0100] > /proc/sys/sunrpc/rpc_debug

I've noticed that those messages always appear in the same pattern:

svc: server c7a3d200 waiting for data (to = 3600000)
svc: socket c6dbfb00(inet c769f220), write_space busy=0
svc: socket c2a9fac0 TCP data ready (svsk c6dbf980)
svc: socket c2a9fac0 served by daemon c7a3d200
svc: socket c2a9fac0 TCP data ready (svsk c6dbf980)
svc: socket c2a9fac0 busy, not enqueued
svc: server c7a3d200, socket c6dbf980, inuse=1
svc: tcp_recv c6dbf980 data 1 conn 0 close 0
svc: socket c6dbf980 recvfrom(c6dbf9d8, 0) = 4
svc: TCP record, 2584 bytes
svc: socket c6dbf980 recvfrom(c6d06a18, 1512) = 2584
svc: TCP complete record (2584 bytes)
svc: socket c2a9fac0 served by daemon c6efe000
svc: got len=2584
svc: socket c2a9fac0 busy, not enqueued
svc: socket c6dbf980 sendto([c436b000 140... ], 140) = 140 (addr 43e17cc1)
svc: socket c2a9fac0 busy, not enqueued
svc: server c7a3d200 waiting for data (to = 3600000)
svc: server c7a3d200, socket c25007a0, inuse=1
svc: tcp_recv c25007a0 data 0 conn 0 close 1
svc: svc_delete_socket(c25007a0)
svc: server socket destroy delayed
svc: got len=0
RPC request reserved 0 but used 140
svc: releasing dead socket
svc: server c7a3d200 waiting for data (to = 3600000)


Note that "tcp_recv" with this set of parameters (data=0 conn=0 close=1)
is always correlated with "RPC request reserved ...", and also the
"used" request length matches the message length in "sendto" on the
seemingly unrelated socket.

Unfortunately I don't understand the code well enough to make a better
bug report, but feel free to ask me to test your patches if you can't
reproduce the problem in your setup.

  Roman.