I also saw this crop up today; I'm not sure if it's related. I'm happy to open a separate ticket if it isn't.

[  +0.000116] WARNING: at fs/nfsd/nfs4state.c:3853 nfsd4_process_open2+0xb72/0xf70 [nfsd]()
[  +0.000125] Modules linked in: nfsv4 dns_resolver nfs fscache cts rpcsec_gss_krb5 ipt_REJECT nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack iptable_filter raid456 async_raid6_recov async_memcpy async_pq xfs raid6_pq async_xor libcrc32c xor async_tx iTCO_wdt iTCO_vendor_support ppdev coretemp kvm pcspkr ipmi_ssif i2c_i801 lpc_ich mfd_core i5400_edac edac_core i5k_amb ioatdma sg parport_pc ipmi_si parport ipmi_msghandler shpchp acpi_cpufreq nfsd nfs_acl lockd grace auth_rpcgss sunrpc ip_tables ext4 mbcache jbd2 raid1 sd_mod crc_t10dif crct10dif_generic crct10dif_common radeon drm_kms_helper ttm igb ahci libahci serio_raw drm ptp libata pps_core dca i2c_algo_bit i2c_core 3w_9xxx dm_mirror dm_region_hash dm_log dm_mod
[  +0.002162] CPU: 3 PID: 2889 Comm: nfsd Tainted: G          I    ------------   3.10.0-327.4.4.el7.x86_64 #1
[  +0.000154] Hardware name: Supermicro X7DW3/X7DWN+, BIOS 1.2c 11/19/2010
[  +0.000101]  0000000000000000 00000000ce9d54d5 ffff880fc701fc28 ffffffff8163515c
[  +0.000161]  ffff880fc701fc60 ffffffff8107b200 ffff880817edf618 ffff880fcaf1e3e0
[  +0.000175]  ffff880035a5eae0 ffff880fc5980d00 0000000000000000 ffff880fc701fc70
[  +0.000160] Call Trace:
[  +0.000050]  [<ffffffff8163515c>] dump_stack+0x19/0x1b
[  +0.000081]  [<ffffffff8107b200>] warn_slowpath_common+0x70/0xb0
[  +0.000094]  [<ffffffff8107b34a>] warn_slowpath_null+0x1a/0x20
[  +0.000096]  [<ffffffffa048ee22>] nfsd4_process_open2+0xb72/0xf70 [nfsd]
[  +0.000112]  [<ffffffffa047e14a>] nfsd4_open+0x55a/0x850 [nfsd]
[  +0.000099]  [<ffffffffa047e917>] nfsd4_proc_compound+0x4d7/0x7f0 [nfsd]
[  +0.000109]  [<ffffffffa046a12b>] nfsd_dispatch+0xbb/0x200 [nfsd]
[  +0.000128]  [<ffffffffa042f183>] svc_process_common+0x453/0x6f0 [sunrpc]
[  +0.000119]  [<ffffffffa042f523>] svc_process+0x103/0x170 [sunrpc]
[  +0.000106]  [<ffffffffa0469ab7>] nfsd+0xe7/0x150 [nfsd]
[  +0.000090]  [<ffffffffa04699d0>] ? nfsd_destroy+0x80/0x80 [nfsd]
[  +0.000099]  [<ffffffff810a5aef>] kthread+0xcf/0xe0
[  +0.000083]  [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
[  +0.000099]  [<ffffffff81645818>] ret_from_fork+0x58/0x90
[  +0.000088]  [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
[  +0.000096] ---[ end trace ecfd01332a02e6a9 ]---

Thanks for marking this public.

On #linux-nfs, bfields mentioned that perhaps the WARNING from comment 2 is related to bug 1233284.  I can't see that bug, though.

(In reply to Jason Tibbitts from comment #3)
> Thanks for marking this public.
> 
> On #linux-nfs, bfields mentioned that perhaps the WARNING from comment 2 is
> related to bug 1233284.  I can't see that bug, though.

I think it should be visible now.

I thought I recalled it fixing a warning like the one you posted in comment 2.  But I see now that it was fixed in -325, and you're on -327, so I was wrong.  (And of course that may be unrelated to the problem reported in the original description.)

Also possibly relevant, from upstream:

35a92fe8770c "nfsd: serialize state seqid morphing operations"
7fc0564e3a8d "nfsd: fix race with open / open upgrade stateids"

Yeah, I don't think 1233284 is the same thing.  I think you were just guessing at the bug number as you were heading out the door.

Thanks for the response.  I booted back to the 3.10.0-327.3.1 kernel just in case.  I've seen the warning again, but so far not the soft lockup (though that usually takes a couple of days).

Someone mentioned disabling NFSv4.1 as a possible workaround, which I'll try the next time I run into the issue.

(In reply to Jason Tibbitts from comment #0)
> I'm using Centos 7.2, so perhaps this bug doesn't interest you, but I don't
> think there's anything here that's different from RHEL7.2 so perhaps it
> does.  This is quite similar to the Fedora bug
> https://bugzilla.redhat.com/show_bug.cgi?id=1185519 which I believe was
> fixed sometime around mainline 3.18.9.

Apologies, I completely missed this.  I agree that that's likely to be the same problem.  The patch referenced on that bug was committed upstream as c876486be17aeefe0da569f3d111cbd8de6f675d, and applies cleanly to rhel7.

I've built and booted into a 3.10.0-327.4.5 kernel with that single line patch applied.  It's far too early to tell if it fixes the problem but given that the patch fixes a pretty obvious cut and paste error, I'm pretty sure it will help.

*** Bug 1303013 has been marked as a duplicate of this bug. ***

I built the 3.10.0-327.4.5 with the patch too. It's been running for three days now and there have been no more laundromat errors (see https://bugzilla.redhat.com/show_bug.cgi?id=1303013#c2 for my error messages) and no more CPU lockups since.

I also just wanted to note that the patched kernel has been running for several days with no random reboots, no soft lockups _and_ no warnings, either.  I hesitate to hope that all three were related to this one issue, but I'll take what I can get.  My thanks to steved and bfields.  This might have been easier for us non-RH people to debug if all of our separate tickets weren't private, but I guess that's just how RH bugzilla works these days.

(In reply to Zenon Panoussis from comment #12)
> I built the 3.10.0-327.4.5 with the patch too. It's been running for three
> days now...

(In reply to Jason Tibbitts from comment #14)
> I also just wanted to note that the patched kernel has been running for
> several days with no random reboots, no soft lockups _and_ no warnings,
> either.

Thanks for the reports!

> This might have been easier for us non-RH people to debug if all of our
> separate tickets weren't private

Feel free to ask about those.  We can't do much about the defaults, but we can often open up individual bugs if it'd help track down some issue.

Before I dig into the source, is there any chance this one-liner is in 3.10.0-327.10.1.el7?

(In reply to Jason Tibbitts from comment #18)
> Before I dig into the source, is there any chance this one-liner is in
> 3.10.0-327.10.1.el7?

It's not there yet.. I'll see if we can move this one along.

Patch(es) available on kernel-3.10.0-351.el7

(In reply to Yongcheng Yang from comment #24)
> Hi Benjamin, could you recall how to reproduce this issue as you mentioned
> at https://bugzilla.redhat.com/show_bug.cgi?id=1185519#c3

Sure.. I had an NFS client w/ iptables rules that used the basic ESTABLISHED,RELATED state rule that come stock on RHEL.  This allows inbound traffic if the traffic is held in netfilter's connection tracking tables.

Then, I would tune down the GC timeouts for those tables to something like 10 seconds using:

echo 10 > /proc/sys/net/netfilter/nf_conntrack_tcp_timeout_established
echo 10 > /proc/sys/net/netfilter/nf_conntrack_tcp_timeout_time_wait

This is is basically preparing the client to be always be able to send packets to the server, but if there is no traffic for longer than 10 seconds the server will be unable to contact the client.   This is a convenient method of simulating callback channel failure without breaking the TCP connection.

The next step is to take a read delegation (on linux usually you need to OPEN the same file twice for read).  Ensure via network capture that the server is granting this delegation.

Then do nothing for 10 seconds (no network traffic for 10 seconds) which will allow netfilter's connection tracking entries to expire.

Then modify that same file on the server -- this is going to cause the server to try to recall the read delegation, but that traffic will be blocked by netfilter.

If I recall correctly, that sets up the problem.

Using a tuned netfilter on the client to simulate this problem is a good QA test anyway, since RHEL has connection tracking set up in iptables out of the box.  A client that takes delegations for longer than the connection tracking timeouts can get into troubles..

Could someone confirm that this is corrected in kernel-3.10.0-327.18.2.el7?

RHSA-2016:1033 - Security Advisory:

A bug in the code that cleans up revoked delegations could previously cause a soft lockup in the NFS server. This patch fixes the underlying source code, so the lockup no longer occurs. (BZ#1311582)

Thank You!

(In reply to Luc Lalonde from comment #37)
> Could someone confirm that this is corrected in kernel-3.10.0-327.18.2.el7?

Hi Luc.  No, this fix has not landed in any released RHEL yet..

I'm getting the same error as in comment #2.  Could someone answer the question if it related to this ticket or BZ#1311582?

Would it be possible to make BZ#1311582 public?

(In reply to Luc Lalonde from comment #39)
> I'm getting the same error as in comment #2.  Could someone answer the
> question if it related to this ticket or BZ#1311582?
> 
> Would it be possible to make BZ#1311582 public?

I add you to the cc list so you should be able to see it...

(In reply to Benjamin Coddington from comment #38)

Hello Benjamin, thanks for your quick reply.

However, it seems that the upstream patch mentioned in comment #6 has been included in kernel-3.10.0-327.18.2.el7:

###########################################################################
[linux-3.10.0-327.18.3.el7]# patch -p1 < ../nfs4state.patch 
patching file fs/nfsd/nfs4state.c
Reversed (or previously applied) patch detected!  Assume -R? [n] 
Apply anyway? [n] 
Skipping patch.
1 out of 1 hunk ignored -- saving rejects to file fs/nfsd/nfs4state.c.rej
###########################################################################

Is this fix incomplete?  Subsequent comments seems to state that this resolves the issues.

(In reply to Steve Dickson from comment #40)
Thanks for adding me to the cc list for BZ1311582... Not much there though, BZ copied from another private BZ.

(In reply to Luc Lalonde from comment #41)
Yes, you are absolutely right.  I apologize.

We don't typically release errata with fixes that haven't completed the bugzilla cycle, but this one went in bug 1311582.

(In reply to Luc Lalonde from comment #37)
> Could someone confirm that this is corrected in kernel-3.10.0-327.18.2.el7?
> 
> RHSA-2016:1033 - Security Advisory:
> 
> A bug in the code that cleans up revoked delegations could previously cause
> a soft lockup in the NFS server. This patch fixes the underlying source
> code, so the lockup no longer occurs. (BZ#1311582)
> 
> Thank You!

You may have already figured this out, but bugzilla 1311582 is a clone of this bug for the RHEL7.2.z ("z-stream" / EUS) kernel series.  There is an errata release for that bugzilla and it has a Fixed In kernel version of kernel-3.10.0-327.18.1.el7.  So yes, the problem reported in this bugzilla should be fixed in kernel-3.10.0-327.18.2.el7.

This problem is not fixed in any RHEL7 y-stream bug though - I think this may be some of the confusion here.  This specific bugzilla won't have an errata until a subsequent RHEL7 y-stream is shipped.  This bugzilla is on track for the next release, RHEL7.3.

Please note that the z-stream bugzillas do go through a test cycle, though it is not as long as a y-stream.  Issues are normally reported against a y-stream release, then if the issue and fix passes risk / reward assessment, the y-stream bug may get cloned for a z-stream as was the case here.

I have updated our kbase solution https://access.redhat.com/solutions/2252701 to reflect that this issue has been fixed in kernel-3.10.0-327.18.2.el7 or above.

After mounting some clients with v4.1 and increasing server threads through /proc we got this warning, followed by a complete lockup of the server about an hour later:

Jul 12 21:18:39 store1 kernel: ------------[ cut here ]------------
Jul 12 21:18:39 store1 kernel: WARNING: at fs/nfsd/nfs4state.c:3853 nfsd4_process_open2+0xb72/0xf70 [nfsd]()
Jul 12 21:18:39 store1 kernel: Modules linked in: fuse btrfs zlib_deflate raid6_pq xor vfat msdos fat ext4 mbcache jbd2 binfmt_misc rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache drbd(OE)
nf_log_ipv4 nf_log_common xt_LOG xt_limit ipt_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ip6table_filter ip6_tables iptable_filter m
gag200 syscopyarea sysfillrect sysimgblt ttm coretemp drm_kms_helper drm kvm_intel iTCO_wdt kvm iTCO_vendor_support i2c_i801 sg pcspkr tpm_infineon lpc_ich mfd_core i7core_edac ioatdma eda
c_core shpchp acpi_cpufreq nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sd_mod crc_t10dif crct10dif_generic crct10dif_common sr_mod cdrom ahci libahci crc32c_intel s
erio_raw libata igb ptp megaraid_sas pps_core i2c_algo_bit i2c_core dca dm_mirror
Jul 12 21:18:39 store1 kernel: dm_region_hash dm_log dm_mod
Jul 12 21:18:39 store1 kernel: CPU: 0 PID: 22113 Comm: nfsd Tainted: G         OE  ------------   3.10.0-327.18.2.el7.x86_64 #1
Jul 12 21:18:39 store1 kernel: Hardware name: Supermicro X8DTU/X8DTU, BIOS 2.0a       09/28/10
Jul 12 21:18:39 store1 kernel: 0000000000000000 0000000091bc746d ffff8804cd97bc28 ffffffff81635a0c
Jul 12 21:18:39 store1 kernel: ffff8804cd97bc60 ffffffff8107b200 ffff880127b851e0 ffff88037d59b3e0
Jul 12 21:18:39 store1 kernel: ffff88049c1ec9f8 ffff880462da3400 0000000000000000 ffff8804cd97bc70
Jul 12 21:18:39 store1 kernel: Call Trace:
Jul 12 21:18:39 store1 kernel: [<ffffffff81635a0c>] dump_stack+0x19/0x1b
Jul 12 21:18:39 store1 kernel: [<ffffffff8107b200>] warn_slowpath_common+0x70/0xb0
Jul 12 21:18:39 store1 kernel: [<ffffffff8107b34a>] warn_slowpath_null+0x1a/0x20
Jul 12 21:18:39 store1 kernel: [<ffffffffa02dae22>] nfsd4_process_open2+0xb72/0xf70 [nfsd]
Jul 12 21:18:39 store1 kernel: [<ffffffffa02ca14a>] nfsd4_open+0x55a/0x850 [nfsd]
Jul 12 21:18:39 store1 kernel: [<ffffffffa02ca917>] nfsd4_proc_compound+0x4d7/0x7f0 [nfsd]
Jul 12 21:18:39 store1 kernel: [<ffffffffa02b612b>] nfsd_dispatch+0xbb/0x200 [nfsd]
Jul 12 21:18:39 store1 kernel: [<ffffffffa027b183>] svc_process_common+0x453/0x6f0 [sunrpc]
Jul 12 21:18:39 store1 kernel: [<ffffffffa027b523>] svc_process+0x103/0x170 [sunrpc]
Jul 12 21:18:39 store1 kernel: [<ffffffffa02b5ab7>] nfsd+0xe7/0x150 [nfsd]
Jul 12 21:18:39 store1 kernel: [<ffffffffa02b59d0>] ? nfsd_destroy+0x80/0x80 [nfsd]
Jul 12 21:18:39 store1 kernel: [<ffffffff810a5aef>] kthread+0xcf/0xe0
Jul 12 21:18:39 store1 kernel: [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
Jul 12 21:18:39 store1 kernel: [<ffffffff81646118>] ret_from_fork+0x58/0x90
Jul 12 21:18:39 store1 kernel: [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
Jul 12 21:18:39 store1 kernel: ---[ end trace 25df83b9611f8b30 ]---

(In reply to rhbug from comment #44)
> After mounting some clients with v4.1 and increasing server threads through
> /proc we got this warning, followed by a complete lockup of the server about
> an hour later:

Thanks for the report, but there's no reason to believe you're seeing the same bug--please open a new one.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2016-2574.html