Bug 1300023 - soft lockup in nfs4_put_stid with 3.10.0-327.4.4.el7
soft lockup in nfs4_put_stid with 3.10.0-327.4.4.el7
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: kernel (Show other bugs)
7.2
Unspecified Unspecified
unspecified Severity unspecified
: rc
: ---
Assigned To: J. Bruce Fields
Yongcheng Yang
Jana Heves
: ZStream
: 1303013 (view as bug list)
Depends On:
Blocks: 1311582 1326899
  Show dependency treegraph
 
Reported: 2016-01-19 14:00 EST by Jason Tibbitts
Modified: 2016-11-03 11:08 EDT (History)
17 users (show)

See Also:
Fixed In Version: kernel-3.10.0-351.el7
Doc Type: Bug Fix
Doc Text:
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.
Story Points: ---
Clone Of:
: 1311582 (view as bug list)
Environment:
Last Closed: 2016-11-03 11:08:04 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 2252701 None None None 2016-04-11 14:05 EDT

  None (edit)
Description Jason Tibbitts 2016-01-19 14:00:41 EST
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.

In any case, I have a server exporting many filesystems via NFS4, with sec=krb5p _only_ (no sec=sys) and it's seeing occasional soft lockups leading to total machine hangs.  (There are other NFS-related problems as well, but this is the only one I can pin down currently and I guess it could be the source of all of them.)  In case it matters, have other machines with similar load running the same kernel version which don't seem to have this issue.  They're all exporting NFS4, but they export with sec=sys.

The soft lockups are logged as follows:

Jan 18 14:23:15 nas05 kernel: BUG: soft lockup - CPU#3 stuck for 22s! [nfsd:2876]
Jan 18 14:23:15 nas05 kernel: 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 lpc_ich mfd_core i2c_i801 parport_pc i5400_edac ioatdma edac_core sg parport i5k_amb ipmi_si 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 drm ptp libata pps_core serio_raw dca i2c_algo_bit i2c_core 3w_9xxx dm_mirror dm_region_hash dm_log dm_mod
Jan 18 14:23:15 nas05 kernel: CPU: 3 PID: 2876 Comm: nfsd Tainted: G          I    ------------   3.10.0-327.4.4.el7.x86_64 #1
Jan 18 14:23:15 nas05 kernel: Hardware name: Supermicro X7DW3/X7DWN+, BIOS 1.2c 11/19/2010
Jan 18 14:23:15 nas05 kernel: task: ffff880fd7e4d080 ti: ffff880fc2cec000 task.ti: ffff880fc2cec000
Jan 18 14:23:15 nas05 kernel: RIP: 0010:[<ffffffff8163c9bb>]  [<ffffffff8163c9bb>] _raw_spin_unlock_irqrestore+0x1b/0x40
Jan 18 14:23:15 nas05 kernel: RSP: 0018:ffff880fc2cefc58  EFLAGS: 00000246
Jan 18 14:23:15 nas05 kernel: RAX: ffffffffa04a3970 RBX: ffff880089ad0500 RCX: ffffffffa04a3988
Jan 18 14:23:15 nas05 kernel: RDX: ffffffffa04a3988 RSI: 0000000000000246 RDI: 0000000000000246
Jan 18 14:23:15 nas05 kernel: RBP: ffff880fc2cefc60 R08: 0000000000000000 R09: 000000010020000a
Jan 18 14:23:15 nas05 kernel: R10: ffffffffa048b2a8 R11: ffffea000226b400 R12: ffffffff81230a24
Jan 18 14:23:15 nas05 kernel: R13: ffffffff81631a45 R14: ffff880fc2cefc58 R15: ffff880fef003700
Jan 18 14:23:15 nas05 kernel: FS:  0000000000000000(0000) GS:ffff88102fcc0000(0000) knlGS:0000000000000000
Jan 18 14:23:15 nas05 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Jan 18 14:23:15 nas05 kernel: CR2: 00007fe454b64000 CR3: 000000000194a000 CR4: 00000000000407e0
Jan 18 14:23:15 nas05 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jan 18 14:23:15 nas05 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Jan 18 14:23:15 nas05 kernel: Stack:
Jan 18 14:23:15 nas05 kernel: ffffffffa04a3980 ffff880fc2cefc98 ffffffff810b0d84 ffff880fc2cefc88
Jan 18 14:23:15 nas05 kernel: ffffffffa048b8d5 ffffffffa048b595 ffff880fc2cefcd8 ffff8800c13cbb58
Jan 18 14:23:15 nas05 kernel: ffff880fc2cefcc8 ffffffffa048b595 ffff880fc2cefcd8 ffff880fc44e1000
Jan 18 14:23:15 nas05 kernel: Call Trace:
Jan 18 14:23:15 nas05 kernel: [<ffffffff810b0d84>] __wake_up+0x44/0x50
Jan 18 14:23:15 nas05 kernel: [<ffffffffa048b8d5>] ? __destroy_client+0x135/0x180 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa048b595>] ? nfs4_put_stid+0x75/0x80 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa048b595>] nfs4_put_stid+0x75/0x80 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa048b88f>] __destroy_client+0xef/0x180 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa048b942>] expire_client+0x22/0x30 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa048c483>] nfsd4_create_session+0x673/0x860 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa047e917>] nfsd4_proc_compound+0x4d7/0x7f0 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa046a12b>] nfsd_dispatch+0xbb/0x200 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa0417183>] svc_process_common+0x453/0x6f0 [sunrpc]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa0417523>] svc_process+0x103/0x170 [sunrpc]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa0469ab7>] nfsd+0xe7/0x150 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffffa04699d0>] ? nfsd_destroy+0x80/0x80 [nfsd]
Jan 18 14:23:15 nas05 kernel: [<ffffffff810a5aef>] kthread+0xcf/0xe0
Jan 18 14:23:15 nas05 kernel: [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
Jan 18 14:23:15 nas05 kernel: [<ffffffff81645818>] ret_from_fork+0x58/0x90
Jan 18 14:23:15 nas05 kernel: [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
Jan 18 14:23:15 nas05 kernel: Code: 08 e8 3a 73 a4 ff 5d c3 0f 1f 84 00 00 00 00 00 66 66 66 66 90 55 48 89 e5 53 48 89 f3 66 66 66 66 90 66 83 07 02 48 89 df 57 9d <66> 66 90 66 90 5b 5d c3 0f 1f 44 00 00 8b 37 f0 66 83 07 02 f6
Jan 18 14:23:44 nas05 kernel: BUG: soft lockup - CPU#3 stuck for 22s! [nfsd:2876]
Jan 18 14:23:44 nas05 kernel: 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 lpc_ich mfd_core i2c_i801 parport_pc i5400_edac ioatdma edac_core sg parport i5k_amb ipmi_si 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 drm ptp libata pps_core serio_raw dca i2c_algo_bit i2c_core 3w_9xxx dm_mirror dm_region_hash dm_log dm_mod
Jan 18 14:23:44 nas05 kernel: CPU: 3 PID: 2876 Comm: nfsd Tainted: G          I  L ------------   3.10.0-327.4.4.el7.x86_64 #1
Jan 18 14:23:44 nas05 kernel: Hardware name: Supermicro X7DW3/X7DWN+, BIOS 1.2c 11/19/2010
Jan 18 14:23:44 nas05 kernel: task: ffff880fd7e4d080 ti: ffff880fc2cec000 task.ti: ffff880fc2cec000
Jan 18 14:23:44 nas05 kernel: RIP: 0010:[<ffffffff8163cb99>]  [<ffffffff8163cb99>] _raw_spin_lock_irqsave+0x9/0x60
Jan 18 14:23:44 nas05 kernel: RSP: 0018:ffff880fc2cefc60  EFLAGS: 00000246
Jan 18 14:23:44 nas05 kernel: RAX: 0000000000000000 RBX: ffffffffa048b2a8 RCX: 0000000000000000
Jan 18 14:23:44 nas05 kernel: RDX: 0000000000000000 RSI: 0000000000000003 RDI: ffffffffa04a3980
Jan 18 14:23:44 nas05 kernel: RBP: ffff880fc2cefc60 R08: ffff880fc2cefcd8 R09: 000000010020000a
Jan 18 14:23:44 nas05 kernel: R10: ffffffffa048b2a8 R11: ffffea000226b400 R12: ffff880089ad0500
Jan 18 14:23:44 nas05 kernel: R13: ffff880fc2cefc60 R14: ffffffff81230a24 R15: ffffffff81631a45
Jan 18 14:23:44 nas05 kernel: FS:  0000000000000000(0000) GS:ffff88102fcc0000(0000) knlGS:0000000000000000
Jan 18 14:23:44 nas05 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Jan 18 14:23:44 nas05 kernel: CR2: 00007fe454b64000 CR3: 000000000194a000 CR4: 00000000000407e0
Jan 18 14:23:44 nas05 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jan 18 14:23:44 nas05 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Jan 18 14:23:44 nas05 kernel: Stack:
Jan 18 14:23:44 nas05 kernel: ffff880fc2cefc98 ffffffff810b0d63 ffff880fc2cefc88 ffffffffa048b8d5
Jan 18 14:23:44 nas05 kernel: ffffffffa048b595 ffff880fc2cefcd8 ffff8800c13cbb58 ffff880fc2cefcc8
Jan 18 14:23:44 nas05 kernel: ffffffffa048b595 ffff880fc2cefcd8 ffff880fc44e1000 ffff880fc2cefc88
Jan 18 14:23:44 nas05 kernel: Call Trace:
Jan 18 14:23:44 nas05 kernel: [<ffffffff810b0d63>] __wake_up+0x23/0x50
Jan 18 14:23:44 nas05 kernel: [<ffffffffa048b8d5>] ? __destroy_client+0x135/0x180 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa048b595>] ? nfs4_put_stid+0x75/0x80 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa048b595>] nfs4_put_stid+0x75/0x80 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa048b88f>] __destroy_client+0xef/0x180 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa048b942>] expire_client+0x22/0x30 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa048c483>] nfsd4_create_session+0x673/0x860 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa047e917>] nfsd4_proc_compound+0x4d7/0x7f0 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa046a12b>] nfsd_dispatch+0xbb/0x200 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa0417183>] svc_process_common+0x453/0x6f0 [sunrpc]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa0417523>] svc_process+0x103/0x170 [sunrpc]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa0469ab7>] nfsd+0xe7/0x150 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffffa04699d0>] ? nfsd_destroy+0x80/0x80 [nfsd]
Jan 18 14:23:44 nas05 kernel: [<ffffffff810a5aef>] kthread+0xcf/0xe0
Jan 18 14:23:44 nas05 kernel: [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
Jan 18 14:23:44 nas05 kernel: [<ffffffff81645818>] ret_from_fork+0x58/0x90
Jan 18 14:23:44 nas05 kernel: [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
Jan 18 14:23:44 nas05 kernel: Code: b8 00 80 00 00 0f b7 0b 66 39 ca 74 ea f3 90 83 e8 01 75 f1 48 89 df 66 66 66 90 66 66 90 eb e0 66 90 66 66 66 66 90 55 48 89 e5 <9c> 58 66 66 90 66 90 49 89 c0 fa 66 66 90 66 66 90 ba 00 00 02
INFO: rcu_sched self-detected stall on CPU { 3}  (t=60000 jiffies g=3462384 c=3462383 q=0)
Jan 18 14:23:50 nas05 kernel: INFO: rcu_sched detected stalls on CPUs/tasks: { 3} (detected by 6, t=60002 jiffies, g=3462384, c=3462383, q=0)
Jan 18 14:23:50 nas05 kernel: sending NMI to all CPUs:
Jan 18 14:23:50 nas05 kernel: NMI backtrace for cpu 2
Jan 18 14:23:50 nas05 kernel: CPU: 2 PID: 0 Comm: swapper/2 Tai

The machine was completely dead at that point; the "Tai" appeared to be the last thing that made it to disk.
Comment 2 Jason Tibbitts 2016-01-19 18:22:09 EST
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 ]---
Comment 3 Jason Tibbitts 2016-01-21 14:47:28 EST
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.
Comment 4 J. Bruce Fields 2016-01-21 15:21:47 EST
(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"
Comment 5 Jason Tibbitts 2016-01-21 15:39:01 EST
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.
Comment 6 J. Bruce Fields 2016-01-27 13:36:17 EST
(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.
Comment 8 Jason Tibbitts 2016-01-27 22:12:47 EST
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.
Comment 9 J. Bruce Fields 2016-01-29 10:16:33 EST
*** Bug 1303013 has been marked as a duplicate of this bug. ***
Comment 12 Zenon Panoussis 2016-02-01 12:48:25 EST
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.
Comment 14 Jason Tibbitts 2016-02-01 16:42:39 EST
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.
Comment 15 J. Bruce Fields 2016-02-01 16:49:43 EST
(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.
Comment 18 Jason Tibbitts 2016-02-17 14:55:17 EST
Before I dig into the source, is there any chance this one-liner is in 3.10.0-327.10.1.el7?
Comment 19 Benjamin Coddington 2016-02-18 13:48:04 EST
(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.
Comment 20 Rafael Aquini 2016-02-24 08:43:06 EST
Patch(es) available on kernel-3.10.0-351.el7
Comment 25 Benjamin Coddington 2016-02-25 05:36:11 EST
(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..
Comment 37 Luc Lalonde 2016-05-24 09:56:49 EDT
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!
Comment 38 Benjamin Coddington 2016-05-24 10:33:34 EDT
(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..
Comment 39 Luc Lalonde 2016-05-25 07:08:35 EDT
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?
Comment 40 Steve Dickson 2016-05-25 08:40:18 EDT
(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...
Comment 41 Luc Lalonde 2016-05-25 10:10:27 EDT
(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.
Comment 42 Benjamin Coddington 2016-05-25 10:27:44 EDT
(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.
Comment 43 Dave Wysochanski 2016-05-25 11:01:18 EDT
(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.
Comment 44 rhbug 2016-07-13 03:33:18 EDT
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 ]---
Comment 45 J. Bruce Fields 2016-07-13 12:09:28 EDT
(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.
Comment 48 errata-xmlrpc 2016-11-03 11:08:04 EDT
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

Note You need to log in before you can comment on or make changes to this bug.