Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Message-ID: <09ad6e031e64820f2efd7495d7467e2bb8b51fc5.camel@linuxfoundation.org>
Subject: TEST_STATEID issues with NFS4.1 and FreeNAS server
From:   Richard Purdie <richard.purdie@linuxfoundation.org>
To:     linux-nfs@vger.kernel.org
Cc:     Michael Halstead <mhalstead@linuxfoundation.org>
Date:   Wed, 20 May 2020 18:47:24 +0100
Content-Type: text/plain; charset="UTF-8"
User-Agent: Evolution 3.36.1-2 
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Sender: linux-nfs-owner@vger.kernel.org
Precedence: bulk

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