Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[Andrew Morton]

(suitable cc added)

(regression)

On Wed, 13 Feb 2008 17:02:53 +0300 Michael Tokarev <mjt@tls.msk.ru> wrote:

> Hello!
> 
> After upgrading to 2.6.24 (from .23), we're seeing ALOT
> of messages like in $subj in dmesg:
> 
> Feb 13 13:21:39 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> Feb 13 13:21:46 paltus kernel: printk: 3586 messages suppressed.
> Feb 13 13:21:46 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> Feb 13 13:21:49 paltus kernel: printk: 371 messages suppressed.
> Feb 13 13:21:49 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> Feb 13 13:21:55 paltus kernel: printk: 2979 messages suppressed.
> ...
> 
> with linux NFS server.  The clients are all linux too, mostly 2.6.23
> and some 2.6.22.
> 
> I found the "offending" piece of code in net/sunrpc/svcsock.c,
> in routine svc_tcp_recvfrom() with condition being:
> 
>    if (svsk->sk_reclen > serv->sv_max_mesg) ...
> 
> This happens after a server reboot.  At this point, client(s) are trying
> to perform some NFS transaction and fail, and server starts generating
> the above messages - till I do a umount followed by mount on all clients.
> Before, such situation (nfs server reboot) were handled transparently,
> ie, there was nothing to do, the mount continued working just fine when
> the server comes back online.
> 
> Now, I'm not sure if it's really 2.6.24-specific problem or a userspace
> problem.  Some time ago we also upgraded nfs-kernel-server (Debian)
> package, and the remount-after-nfs-server-reboot problem started to
> occur at THAT time (and it is something to worry about as well, I just
> had no time to deal with it); but the dmesg spamming only appeared
> with 2.6.24.
> 
> How to debug the issue further on from this point?
> 

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[Michael Tokarev]

Andrew Morton wrote:
> (suitable cc added)

Thanks.  I was meant to sent it to linux-nfs originally, but
looks like i mistyped the address.

> (regression)

Now, after we did some more experiments with it, I don't think it's
a regression.  I'll post a bit more details in a few hours when the
ongoing testing finishes.  Thanks!

/mjt

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[Tom Tucker]

On Mon, 2008-02-18 at 04:58 -0800, Andrew Morton wrote:
> (suitable cc added)
> 
> (regression)
> 
> On Wed, 13 Feb 2008 17:02:53 +0300 Michael Tokarev <mjt@tls.msk.ru> wrote:
> 
> > Hello!
> > 
> > After upgrading to 2.6.24 (from .23), we're seeing ALOT
> > of messages like in $subj in dmesg:
> > 
> > Feb 13 13:21:39 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> > Feb 13 13:21:46 paltus kernel: printk: 3586 messages suppressed.
> > Feb 13 13:21:46 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> > Feb 13 13:21:49 paltus kernel: printk: 371 messages suppressed.
> > Feb 13 13:21:49 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> > Feb 13 13:21:55 paltus kernel: printk: 2979 messages suppressed.
> > ...
> > 
> > with linux NFS server.  The clients are all linux too, mostly 2.6.23
> > and some 2.6.22.
> > 
> > I found the "offending" piece of code in net/sunrpc/svcsock.c,
> > in routine svc_tcp_recvfrom() with condition being:
> > 
> >    if (svsk->sk_reclen > serv->sv_max_mesg) ...

The problem might be that the client is setting a bit in the RPC message
length field that is meant to be interpreted and masked off by the
server -- and we're not doing it yet. My bet is that 0x20000 is the bit
we're looking for. I'll poke around...

> > 
> > This happens after a server reboot.  At this point, client(s) are trying
> > to perform some NFS transaction and fail, and server starts generating
> > the above messages - till I do a umount followed by mount on all clients.
> > Before, such situation (nfs server reboot) were handled transparently,
> > ie, there was nothing to do, the mount continued working just fine when
> > the server comes back online.
> > 
> > Now, I'm not sure if it's really 2.6.24-specific problem or a userspace
> > problem.  Some time ago we also upgraded nfs-kernel-server (Debian)
> > package, and the remount-after-nfs-server-reboot problem started to
> > occur at THAT time (and it is something to worry about as well, I just
> > had no time to deal with it); but the dmesg spamming only appeared
> > with 2.6.24.
> > 
> > How to debug the issue further on from this point?
> > 
> 
> 
> -
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[Tom Tucker]

On Mon, 2008-02-18 at 15:25 -0600, Tom Tucker wrote:
> On Mon, 2008-02-18 at 04:58 -0800, Andrew Morton wrote:
> > (suitable cc added)
> > 
> > (regression)
> > 
> > On Wed, 13 Feb 2008 17:02:53 +0300 Michael Tokarev <mjt@tls.msk.ru> wrote:
> > 
> > > Hello!
> > > 
> > > After upgrading to 2.6.24 (from .23), we're seeing ALOT
> > > of messages like in $subj in dmesg:
> > > 
> > > Feb 13 13:21:39 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> > > Feb 13 13:21:46 paltus kernel: printk: 3586 messages suppressed.
> > > Feb 13 13:21:46 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> > > Feb 13 13:21:49 paltus kernel: printk: 371 messages suppressed.
> > > Feb 13 13:21:49 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
> > > Feb 13 13:21:55 paltus kernel: printk: 2979 messages suppressed.
> > > ...
> > > 
> > > with linux NFS server.  The clients are all linux too, mostly 2.6.23
> > > and some 2.6.22.
> > > 
> > > I found the "offending" piece of code in net/sunrpc/svcsock.c,
> > > in routine svc_tcp_recvfrom() with condition being:
> > > 
> > >    if (svsk->sk_reclen > serv->sv_max_mesg) ...
> 
> The problem might be that the client is setting a bit in the RPC message
> length field that is meant to be interpreted and masked off by the
> server -- and we're not doing it yet. My bet is that 0x20000 is the bit
> we're looking for. I'll poke around...

Never mind. The way this is supposed to work is that the transport is
shut down. The code used to delete the socket directly, but I
reorganized this code to just set the XPT_CLOSE bit and let the normal
close path handle it when it came back through to retry. I'm not sure
exactly what version of the code you have, but it may be that your
missing the code from the close path that does this, or it may just not
work. As a first shot, can you try this patch and tell me if the
messages go away?


diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
index 1d3e5fc..cf6150a 100644
--- a/net/sunrpc/svcsock.c
+++ b/net/sunrpc/svcsock.c
@@ -920,6 +920,7 @@ static int svc_tcp_recvfrom(struct svc_rqst *rqstp)
 
  err_delete:
        set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
+       svc_delete_xprt(&svsk->sk_xprt);
        return -EAGAIN;
 
  error:


> 
> > > 
> > > This happens after a server reboot.  At this point, client(s) are trying
> > > to perform some NFS transaction and fail, and server starts generating
> > > the above messages - till I do a umount followed by mount on all clients.
> > > Before, such situation (nfs server reboot) were handled transparently,
> > > ie, there was nothing to do, the mount continued working just fine when
> > > the server comes back online.
> > > 
> > > Now, I'm not sure if it's really 2.6.24-specific problem or a userspace
> > > problem.  Some time ago we also upgraded nfs-kernel-server (Debian)
> > > package, and the remount-after-nfs-server-reboot problem started to
> > > occur at THAT time (and it is something to worry about as well, I just
> > > had no time to deal with it); but the dmesg spamming only appeared
> > > with 2.6.24.
> > > 
> > > How to debug the issue further on from this point?
> > > 
> > 
> > 
> > -
> > To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> -
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[Tom Tucker]

Michael:

>>>>> On Wed, 13 Feb 2008 17:02:53 +0300 Michael Tokarev <mjt@tls.msk.ru> wrote:
>>>>> 
>>>>>> Hello!
>>>>>> 
>>>>>> After upgrading to 2.6.24 (from .23), we're seeing ALOT
>>>>>> of messages like in $subj in dmesg:
>>>>>> 
>>>>>> Feb 13 13:21:39 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>> Feb 13 13:21:46 paltus kernel: printk: 3586 messages suppressed.
>>>>>> Feb 13 13:21:46 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>> Feb 13 13:21:49 paltus kernel: printk: 371 messages suppressed.
>>>>>> Feb 13 13:21:49 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>> Feb 13 13:21:55 paltus kernel: printk: 2979 messages suppressed.
>>>>>> ...
>>>>>> 

Are you seeing this with the latest bits?  I just want to make sure that
this particular close path issue is fixed.

Thanks,
Tom

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[Michael Tokarev]

Tom Tucker wrote:
> Michael:
> 
>>>>>> On Wed, 13 Feb 2008 17:02:53 +0300 Michael Tokarev <mjt@tls.msk.ru> wrote:
>>>>>>
>>>>>>> Hello!
>>>>>>>
>>>>>>> After upgrading to 2.6.24 (from .23), we're seeing ALOT
>>>>>>> of messages like in $subj in dmesg:
>>>>>>>
>>>>>>> Feb 13 13:21:39 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>> Feb 13 13:21:46 paltus kernel: printk: 3586 messages suppressed.
>>>>>>> Feb 13 13:21:46 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>> Feb 13 13:21:49 paltus kernel: printk: 371 messages suppressed.
>>>>>>> Feb 13 13:21:49 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>> Feb 13 13:21:55 paltus kernel: printk: 2979 messages suppressed.
>>>>>>> ...
>>>>>>>
> 
> Are you seeing this with the latest bits?  I just want to make sure that
> this particular close path issue is fixed.

Err.  I completely forgot about that issue, due to many many other
issues popped up last few weeks...

Ok.

I tried to reproduce it here.  It happened only once here, when I changed
the kernel on the NFS server from 2.6.23-i686 to 2.6.24-x86-64, without
rebooting/remounting clients.  The messages shown above were on the server.
After remounting the filesystem on clients, the message disappeared.

After that, I tried the same thing with other machines (that one was
our main production server so no experiments there) -- same clients but
another server.  I did many reboots with different kernels while the
clients had filesystems mounted - but wasn't able to reproduce the same
messages again.

So I don't really know what happened, and even if whatever happened
was due to single client or not - I wasn't thought about tcpdump at
the time when I were remounting the clients.  Maybe it was a random
glitch, maybe it IS a bug - I don't really know by now.

There was another issue before, when after upgrading the server,
clients were needed to remount stuff or else "ESTALE" were always
returned.  I think it was around 2.6.21=>2.6.22.  Again, I can't
reproduce it anymore (with current kernels).

So I think the case can be closed now - esp. since noone (it seems)
reported similar issues.

Thank you!

/mjt

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[J. Bruce Fields]

On Fri, Mar 14, 2008 at 09:57:00PM +0300, Michael Tokarev wrote:
> Tom Tucker wrote:
>> Michael:
>>
>>>>>>> On Wed, 13 Feb 2008 17:02:53 +0300 Michael Tokarev <mjt@tls.msk.ru> wrote:
>>>>>>>
>>>>>>>> Hello!
>>>>>>>>
>>>>>>>> After upgrading to 2.6.24 (from .23), we're seeing ALOT
>>>>>>>> of messages like in $subj in dmesg:
>>>>>>>>
>>>>>>>> Feb 13 13:21:39 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>>> Feb 13 13:21:46 paltus kernel: printk: 3586 messages suppressed.
>>>>>>>> Feb 13 13:21:46 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>>> Feb 13 13:21:49 paltus kernel: printk: 371 messages suppressed.
>>>>>>>> Feb 13 13:21:49 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>>> Feb 13 13:21:55 paltus kernel: printk: 2979 messages suppressed.
>>>>>>>> ...
>>>>>>>>
>>
>> Are you seeing this with the latest bits?  I just want to make sure that
>> this particular close path issue is fixed.
>
> Err.  I completely forgot about that issue, due to many many other
> issues popped up last few weeks...
>
> Ok.
>
> I tried to reproduce it here.  It happened only once here, when I changed
> the kernel on the NFS server from 2.6.23-i686 to 2.6.24-x86-64, without
> rebooting/remounting clients.  The messages shown above were on the server.
> After remounting the filesystem on clients, the message disappeared.
>
> After that, I tried the same thing with other machines (that one was
> our main production server so no experiments there) -- same clients but
> another server.  I did many reboots with different kernels while the
> clients had filesystems mounted - but wasn't able to reproduce the same
> messages again.
>
> So I don't really know what happened, and even if whatever happened
> was due to single client or not - I wasn't thought about tcpdump at
> the time when I were remounting the clients.  Maybe it was a random
> glitch, maybe it IS a bug - I don't really know by now.
>
> There was another issue before, when after upgrading the server,
> clients were needed to remount stuff or else "ESTALE" were always
> returned.  I think it was around 2.6.21=>2.6.22.  Again, I can't
> reproduce it anymore (with current kernels).
>
> So I think the case can be closed now - esp. since noone (it seems)
> reported similar issues.

OK.  But we do expect clients to continue working normally even when the
server's kernel is upgraded, so continue reporting such problems when
you run across them; hints on how to reproduce such problems are
particularly helpful.

--b.

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[Tom Tucker]

Michael:

Thanks for the update. BTW, the perfect "positive fix indication" would be
seeing a single "...bad TCP reclen..." message in the log for the
reconnecting/confused client.

Thanks,
Tom


On 3/14/08 2:06 PM, "J. Bruce Fields" <bfields@fieldses.org> wrote:

> On Fri, Mar 14, 2008 at 09:57:00PM +0300, Michael Tokarev wrote:
>> Tom Tucker wrote:
>>> Michael:
>>> 
>>>>>>>> On Wed, 13 Feb 2008 17:02:53 +0300 Michael Tokarev <mjt@tls.msk.ru>
>>>>>>>> wrote:
>>>>>>>> 
>>>>>>>>> Hello!
>>>>>>>>> 
>>>>>>>>> After upgrading to 2.6.24 (from .23), we're seeing ALOT
>>>>>>>>> of messages like in $subj in dmesg:
>>>>>>>>> 
>>>>>>>>> Feb 13 13:21:39 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>>>> Feb 13 13:21:46 paltus kernel: printk: 3586 messages suppressed.
>>>>>>>>> Feb 13 13:21:46 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>>>> Feb 13 13:21:49 paltus kernel: printk: 371 messages suppressed.
>>>>>>>>> Feb 13 13:21:49 paltus kernel: RPC: bad TCP reclen 0x00020090 (large)
>>>>>>>>> Feb 13 13:21:55 paltus kernel: printk: 2979 messages suppressed.
>>>>>>>>> ...
>>>>>>>>> 
>>> 
>>> Are you seeing this with the latest bits?  I just want to make sure that
>>> this particular close path issue is fixed.
>> 
>> Err.  I completely forgot about that issue, due to many many other
>> issues popped up last few weeks...
>> 
>> Ok.
>> 
>> I tried to reproduce it here.  It happened only once here, when I changed
>> the kernel on the NFS server from 2.6.23-i686 to 2.6.24-x86-64, without
>> rebooting/remounting clients.  The messages shown above were on the server.
>> After remounting the filesystem on clients, the message disappeared.
>> 
>> After that, I tried the same thing with other machines (that one was
>> our main production server so no experiments there) -- same clients but
>> another server.  I did many reboots with different kernels while the
>> clients had filesystems mounted - but wasn't able to reproduce the same
>> messages again.
>> 
>> So I don't really know what happened, and even if whatever happened
>> was due to single client or not - I wasn't thought about tcpdump at
>> the time when I were remounting the clients.  Maybe it was a random
>> glitch, maybe it IS a bug - I don't really know by now.
>> 
>> There was another issue before, when after upgrading the server,
>> clients were needed to remount stuff or else "ESTALE" were always
>> returned.  I think it was around 2.6.21=>2.6.22.  Again, I can't
>> reproduce it anymore (with current kernels).
>> 
>> So I think the case can be closed now - esp. since noone (it seems)
>> reported similar issues.
> 
> OK.  But we do expect clients to continue working normally even when the
> server's kernel is upgraded, so continue reporting such problems when
> you run across them; hints on how to reproduce such problems are
> particularly helpful.
> 
> --b.

Re: 2.6.24: RPC: bad TCP reclen 0x00020090 (large)

[J. Bruce Fields]

On Fri, Mar 14, 2008 at 02:25:21PM -0500, Tom Tucker wrote:
> 
> Michael:
> 
> Thanks for the update. BTW, the perfect "positive fix indication" would be
> seeing a single "...bad TCP reclen..." message in the log for the
> reconnecting/confused client.

Hm.  This may be entirely unrelated (and not at all your responsibility)
but

	 ./testserver.py server:/ --rundeps -v WRT5

with newpynfs:

	http://www.citi.umich.edu/projects/nfsv4/pynfs/

gets me a "RPC: bad TCP reclen 0x00000800 (non-terminal)" and a test
failure.  Hm.  It may be that newpynfs is doing something intolerably
weird and the server's just dropping the request instead of returning an
error.  OK, probably totally unrelated.  I haven't looked hard enough
yet.

--b.