2020-05-20 17:48:01

by Richard Purdie

[permalink] [raw]
Subject: TEST_STATEID issues with NFS4.1 and FreeNAS server

Hi,

We have a cluster of machines where we're observing file accesses
hanging over NFS. The clients showing the problems are Fedora and SUSE
distros with the 5.6.11 kernel, e.g.:

Linux version 5.6.11-1-default (geeko@buildhost) (gcc version 9.3.1 20200406
[revision 6db837a5288ee3ca5ec504fbd5a765817e556ac2] (SUSE Linux))
#1 SMP Wed May 6 10:42:09 UTC 2020 (91c024a)

In the example below we see a git clone hang, its having trouble
reading a .pack file off the NFS share, the git process is in D state.
I've included part of dmesg below with sysrq-w output.

Mount options:

rw,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,local_lock=none

mountstats shows:

READ:
632014263 ops (62%) 629809108 errors (99%)
TEST_STATEID:
363257078 ops (36%) 363257078 errors (100%)

which is a clue on what is happening. I grabbed some data with tcpdump
and it shows the READ getting NFS4ERR_BAD_STATEID, there is then a
TEST_STATEID which gets NFS4ERR_NOTSUPP. This repeats infinitely in a
loop.

The server is FreeNAS11.3 which does not have:
https://github.com/HardenedBSD/hardenedBSD-stable/commit/63f6f19b0756b18f2e68d82cbe037f21f9a8c500
applied so it will return NFS4ERR_NOTSUPP to TEST_STATEID.

I think something may be needed to stop Linux getting into an infinite
loop with this, regardless of whether the spec says TEST_STATEID can
get a NFS4ERR_NOTSUPP or not?

I freely admit I know little about much of this so I'm open to
pointers. If we did remount as 4.0 we probably wouldn't see the issue
as it would avoid the TEST_STATEID code.

Cheers,

Richard

[249239.124271] NFS: nfs4_reclaim_open_state: unhandled error -524
[249239.124722] NFSv4: state recovery failed for open file git2/github.com.rpm-software-management.dnf.git.lock, error = -524
[249239.124723] NFSv4: state recovery failed for open file git2/github.com.rpm-software-management.dnf.git.lock, error = -524
[249239.124724] NFSv4: state recovery failed for open file git2/github.com.rpm-software-management.dnf.git.lock, error = -524
[249244.947749] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[249244.964169] NFS: nfs4_reclaim_open_state: unhandled error -524
[249244.964646] NFSv4: state recovery failed for open file git2/github.com.rpm-software-management.dnf.git.lock, error = -524
[249244.964648] NFSv4: state recovery failed for open file git2/github.com.rpm-software-management.dnf.git.lock, error = -524
[376912.912171] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[376913.215654] NFS: __nfs4_reclaim_open_state: Lock reclaim failed!
[408558.690581] sysrq: Show Blocked State
[408558.690630] task PC stack pid father
[408558.692490] git D 0 41178 41159 0x00000004
[408558.692494] Call Trace:
[408558.692506] ? __schedule+0x2d8/0x760
[408558.692512] ? blk_finish_plug+0x21/0x2e
[408558.692516] ? read_pages+0x87/0x1a0
[408558.692519] schedule+0x4a/0xb0
[408558.692522] io_schedule+0x12/0x40
[408558.692528] __lock_page_killable+0x131/0x250
[408558.692532] ? file_fdatawait_range+0x20/0x20
[408558.692536] filemap_fault+0x69e/0x9d0
[408558.692540] ? alloc_set_pte+0x118/0x660
[408558.692546] ? __alloc_pages_nodemask+0x166/0x300
[408558.692552] ? xas_load+0x9/0x80
[408558.692556] ? xas_find+0x177/0x1c0
[408558.692559] ? filemap_map_pages+0x8b/0x380
[408558.692562] __do_fault+0x36/0xd0
[408558.692565] do_fault+0x246/0x520
[408558.692569] __handle_mm_fault+0x5d5/0x820
[408558.692573] handle_mm_fault+0xc4/0x1f0
[408558.692579] do_user_addr_fault+0x1f9/0x450
[408558.692585] page_fault+0x3e/0x50
[408558.692589] RIP: 0033:0x561301328dd1
[408558.692596] Code: Bad RIP value.
[408558.692597] RSP: 002b:00007fff69c81e10 EFLAGS: 00010202
[408558.692600] RAX: 00007fc2165118a2 RBX: 00007fff69c81ec8 RCX: 00007fff69c81ec0
[408558.692601] RDX: 00007fff69c81e2c RSI: 00000000001bd2a9 RDI: 00007fc2165118a2
[408558.692602] RBP: 0000561303310ab0 R08: 000000000014e8a2 R09: 0000000000000075
[408558.692604] R10: 00005613014843e0 R11: 0000000000000004 R12: 00007fff69c81ec0
[408558.692605] R13: 0000000000000040 R14: 00007fff69c81f00 R15: 00007fff69c81ed0


2020-05-20 18:02:52

by Trond Myklebust

[permalink] [raw]
Subject: Re: TEST_STATEID issues with NFS4.1 and FreeNAS server

Hi Richard,

On Wed, 2020-05-20 at 18:47 +0100, Richard Purdie wrote:
> Hi,
>
> We have a cluster of machines where we're observing file accesses
> hanging over NFS. The clients showing the problems are Fedora and
> SUSE
> distros with the 5.6.11 kernel, e.g.:
>
> Linux version 5.6.11-1-default (geeko@buildhost) (gcc version 9.3.1
> 20200406
> [revision 6db837a5288ee3ca5ec504fbd5a765817e556ac2] (SUSE Linux))
> #1 SMP Wed May 6 10:42:09 UTC 2020 (91c024a)
>
> In the example below we see a git clone hang, its having trouble
> reading a .pack file off the NFS share, the git process is in D
> state.
> I've included part of dmesg below with sysrq-w output.
>
> Mount options:
>
> rw,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,hard,proto=
> tcp,timeo=600,retrans=2,sec=sys,local_lock=none
>
> mountstats shows:
>
> READ:
> 632014263 ops (62%) 629809108 errors (99%)
> TEST_STATEID:
> 363257078 ops (36%) 363257078 errors (100%)
>
> which is a clue on what is happening. I grabbed some data with
> tcpdump
> and it shows the READ getting NFS4ERR_BAD_STATEID, there is then a
> TEST_STATEID which gets NFS4ERR_NOTSUPP. This repeats infinitely in a
> loop.
>
> The server is FreeNAS11.3 which does not have:
> https://github.com/HardenedBSD/hardenedBSD-stable/commit/63f6f19b0756b18f2e68d82cbe037f21f9a8c500
> applied so it will return NFS4ERR_NOTSUPP to TEST_STATEID.
>
> I think something may be needed to stop Linux getting into an
> infinite
> loop with this, regardless of whether the spec says TEST_STATEID can
> get a NFS4ERR_NOTSUPP or not?
>
> I freely admit I know little about much of this so I'm open to
> pointers. If we did remount as 4.0 we probably wouldn't see the issue
> as it would avoid the TEST_STATEID code.

TEST_STATEID is listed in RFC5661 Section 17 as REQUIRED to implement
for NFSv4.1. We will not be able to support a server that violates that
requirement.

Cheers
Trond

--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
[email protected]


2020-05-20 18:09:05

by Richard Purdie

[permalink] [raw]
Subject: Re: TEST_STATEID issues with NFS4.1 and FreeNAS server

On Wed, 2020-05-20 at 18:01 +0000, Trond Myklebust wrote:
> Hi Richard,
>
> On Wed, 2020-05-20 at 18:47 +0100, Richard Purdie wrote:
> > Hi,
> >
> > We have a cluster of machines where we're observing file accesses
> > hanging over NFS. The clients showing the problems are Fedora and
> > SUSE
> > distros with the 5.6.11 kernel, e.g.:
> >
> > Linux version 5.6.11-1-default (geeko@buildhost) (gcc version 9.3.1
> > 20200406
> > [revision 6db837a5288ee3ca5ec504fbd5a765817e556ac2] (SUSE Linux))
> > #1 SMP Wed May 6 10:42:09 UTC 2020 (91c024a)
> >
> > In the example below we see a git clone hang, its having trouble
> > reading a .pack file off the NFS share, the git process is in D
> > state.
> > I've included part of dmesg below with sysrq-w output.
> >
> > Mount options:
> >
> > rw,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,hard,proto=
> > tcp,timeo=600,retrans=2,sec=sys,local_lock=none
> >
> > mountstats shows:
> >
> > READ:
> > 632014263 ops (62%) 629809108 errors (99%)
> > TEST_STATEID:
> > 363257078 ops (36%) 363257078 errors (100%)
> >
> > which is a clue on what is happening. I grabbed some data with
> > tcpdump
> > and it shows the READ getting NFS4ERR_BAD_STATEID, there is then a
> > TEST_STATEID which gets NFS4ERR_NOTSUPP. This repeats infinitely in a
> > loop.
> >
> > The server is FreeNAS11.3 which does not have:
> > https://github.com/HardenedBSD/hardenedBSD-stable/commit/63f6f19b0756b18f2e68d82cbe037f21f9a8c500
> > applied so it will return NFS4ERR_NOTSUPP to TEST_STATEID.
> >
> > I think something may be needed to stop Linux getting into an
> > infinite
> > loop with this, regardless of whether the spec says TEST_STATEID can
> > get a NFS4ERR_NOTSUPP or not?
> >
> > I freely admit I know little about much of this so I'm open to
> > pointers. If we did remount as 4.0 we probably wouldn't see the issue
> > as it would avoid the TEST_STATEID code.
>
> TEST_STATEID is listed in RFC5661 Section 17 as REQUIRED to implement
> for NFSv4.1. We will not be able to support a server that violates that
> requirement.

Understood, I suspected as much.

Locking systems into an infinite loop doesn't seem like a good user
experience though. Is there a way to handle that more gracefully?

Cheers,

Richard


2020-05-20 18:16:44

by Trond Myklebust

[permalink] [raw]
Subject: Re: TEST_STATEID issues with NFS4.1 and FreeNAS server

On Wed, 2020-05-20 at 19:06 +0100, Richard Purdie wrote:
> On Wed, 2020-05-20 at 18:01 +0000, Trond Myklebust wrote:
> > Hi Richard,
> >
> > On Wed, 2020-05-20 at 18:47 +0100, Richard Purdie wrote:
> > > Hi,
> > >
> > > We have a cluster of machines where we're observing file accesses
> > > hanging over NFS. The clients showing the problems are Fedora and
> > > SUSE
> > > distros with the 5.6.11 kernel, e.g.:
> > >
> > > Linux version 5.6.11-1-default (geeko@buildhost) (gcc version
> > > 9.3.1
> > > 20200406
> > > [revision 6db837a5288ee3ca5ec504fbd5a765817e556ac2] (SUSE
> > > Linux))
> > > #1 SMP Wed May 6 10:42:09 UTC 2020 (91c024a)
> > >
> > > In the example below we see a git clone hang, its having trouble
> > > reading a .pack file off the NFS share, the git process is in D
> > > state.
> > > I've included part of dmesg below with sysrq-w output.
> > >
> > > Mount options:
> > >
> > > rw,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,hard,pr
> > > oto=
> > > tcp,timeo=600,retrans=2,sec=sys,local_lock=none
> > >
> > > mountstats shows:
> > >
> > > READ:
> > > 632014263 ops (62%) 629809108 errors (99%)
> > > TEST_STATEID:
> > > 363257078 ops (36%) 363257078 errors (100%)
> > >
> > > which is a clue on what is happening. I grabbed some data with
> > > tcpdump
> > > and it shows the READ getting NFS4ERR_BAD_STATEID, there is then
> > > a
> > > TEST_STATEID which gets NFS4ERR_NOTSUPP. This repeats infinitely
> > > in a
> > > loop.
> > >
> > > The server is FreeNAS11.3 which does not have:
> > > https://github.com/HardenedBSD/hardenedBSD-stable/commit/63f6f19b0756b18f2e68d82cbe037f21f9a8c500
> > > applied so it will return NFS4ERR_NOTSUPP to TEST_STATEID.
> > >
> > > I think something may be needed to stop Linux getting into an
> > > infinite
> > > loop with this, regardless of whether the spec says TEST_STATEID
> > > can
> > > get a NFS4ERR_NOTSUPP or not?
> > >
> > > I freely admit I know little about much of this so I'm open to
> > > pointers. If we did remount as 4.0 we probably wouldn't see the
> > > issue
> > > as it would avoid the TEST_STATEID code.
> >
> > TEST_STATEID is listed in RFC5661 Section 17 as REQUIRED to
> > implement
> > for NFSv4.1. We will not be able to support a server that violates
> > that
> > requirement.
>
> Understood, I suspected as much.
>
> Locking systems into an infinite loop doesn't seem like a good user
> experience though. Is there a way to handle that more gracefully?
>

As I implied above, this is a 'server from hell' scenario that we
really can't be expected to support at all. I suggest downgrading to
NFSv4.0 until you can get a fix for the server.

--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
[email protected]