Bug 1368577

Created attachment 1192291 [details]
netconsole.log.xz - part 2/2

Second part of the netconsole.log.xz file.

I think this is actually several different bugs. The first WARN is interesting, but harmless.

The second one in rpc_exit_task is interesting. Perhaps we have a race of some sort when tearing down a backchannel transport? It seems like some of the RPC tasks might not have gotten torn down correctly.

The third stack trace is probably the problem that was fixed by 3fcbbd244ed1d20dc0eb7d48d729503992fa9b7d upstream, or maybe a few of the other patches that went in around that time. I think Bruce has backported that, so you may want to try a more recent rhel7 kernel, as that's a clear memory corruptor.

The remaining softlockups are probably fallout from the problem that caused the 3rd stack trace.

Hi,

Thanks for your prompt reply.

(In reply to Jeff Layton from comment #3)
> I think this is actually several different bugs. The first WARN is
> interesting, but harmless.
> 
> The second one in rpc_exit_task is interesting. Perhaps we have a race of
> some sort when tearing down a backchannel transport? It seems like some of
> the RPC tasks might not have gotten torn down correctly.
> 
> The third stack trace is probably the problem that was fixed by
> 3fcbbd244ed1d20dc0eb7d48d729503992fa9b7d upstream, or maybe a few of the
> other patches that went in around that time. I think Bruce has backported
> that, so you may want to try a more recent rhel7 kernel, as that's a clear
> memory corruptor.

3.10.0-327.28.3.el7 seems to be the latest available kernel and compared to 28.2 it only contains a security fix? Where can I find more recent kernels?

> The remaining softlockups are probably fallout from the problem that caused
> the 3rd stack trace.

Any idea on the following messages:
receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt ffff8800bae57000 xid 570c89f3

We are seeing lots of them (but they don't seem to crash the box on their own). The only thing I could find online about these messages is about exporting an XFS filesystem and the bug should be fixed in the RHEL 7.2 kernel.

I have another netconsole capture from the same system and this includes a final PANIC message:

[243229.909545] Kernel panic - not syncing: Fatal exception
[243229.919826] drm_kms_helper: panic occurred, switching back to text console
[243229.920805] ------------[ cut here ]------------
[243229.921780] WARNING: at arch/x86/kernel/smp.c:124 native_smp_send_reschedule+0x5f/0x70()
[243229.922772] Modules linked in: netconsole fuse rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache 8021q garp stp mrp llc xt_set xt_multiport ip_set_hash_ip ip_set nfnetlink bonding ipt_REJECT nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack iptable_filter dm_snapshot dm_bufio intel_powerclamp coretemp kvm_intel kvm crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel lrw ixgbe gf128mul bnx2 glue_helper ablk_helper iTCO_wdt cryptd dm_service_time iTCO_vendor_support ptp pps_core mdio dca lpc_ich dcdbas mfd_core sg i7core_edac shpchp edac_core pcspkr ipmi_devintf ipmi_si ipmi_msghandler wmi acpi_power_meter acpi_cpufreq binfmt_misc nfsd auth_rpcgss nfs_acl lockd grace sunrpc dm_multipath ip_tables ext4 mbcache jbd2 sd_mod sr_mod cdrom ata_generic pata_acpi mgag200 syscopyarea sysfillrect sysimgblt i2c_algo_bit lpfc drm_kms_helper ttm crc_t10dif drm crct10dif_generic mpt2sas ata_piix crct10dif_pclmul scsi_transport_fc serio_raw raid_class libata i2c_core scsi_tgt scsi_transport_sas crct10dif_common dm_mirror dm_region_hash dm_log dm_mod
[243229.933053] CPU: 0 PID: 3331 Comm: nfsd Tainted: G      D W I    ------------   3.10.0-327.28.2.el7.x86_64 #1
[243229.934239] Hardware name: Dell Inc. PowerEdge R710/0MD99X, BIOS 6.3.0 07/24/2012
[243229.935409]  0000000000000000 000000004a89d18c ffff88121b203d98 ffffffff81636553
[243229.936576]  ffff88121b203dd0 ffffffff8107b200 0000000000000001 ffff88121b2167c0
[243229.937723]  000000010e7a9b5e ffff88091ba167c0 0000000000000000 ffff88121b203de0
[243229.938846] Call Trace:
[243229.939924]  <IRQ>  [<ffffffff81636553>] dump_stack+0x19/0x1b
[243229.941007]  [<ffffffff8107b200>] warn_slowpath_common+0x70/0xb0
[243229.942057]  [<ffffffff8107b34a>] warn_slowpath_null+0x1a/0x20
[243229.943076]  [<ffffffff8104684f>] native_smp_send_reschedule+0x5f/0x70
[243229.944084]  [<ffffffff810c650d>] trigger_load_balance+0x16d/0x200
[243229.945074]  [<ffffffff810b7703>] scheduler_tick+0x103/0x150
[243229.946052]  [<ffffffff810e08a0>] ? tick_sched_handle.isra.14+0x60/0x60
[243229.947033]  [<ffffffff8108e926>] update_process_times+0x66/0x80
[243229.948104]  [<ffffffff810e0865>] tick_sched_handle.isra.14+0x25/0x60
[243229.949075]  [<ffffffff810e08e1>] tick_sched_timer+0x41/0x70
[243229.950040]  [<ffffffff810a9d82>] __hrtimer_run_queues+0xd2/0x260
[243229.951004]  [<ffffffff810aa320>] hrtimer_interrupt+0xb0/0x1e0
[243229.951974]  [<ffffffff8164855c>] ? call_softirq+0x1c/0x30
[243229.952941]  [<ffffffff810495c7>] local_apic_timer_interrupt+0x37/0x60
[243229.953915]  [<ffffffff816491cf>] smp_apic_timer_interrupt+0x3f/0x60
[243229.954889]  [<ffffffff8164789d>] apic_timer_interrupt+0x6d/0x80
[243229.955858]  <EOI>  [<ffffffffa0143853>] ? __drm_modeset_lock_all+0x33/0x110 [drm]
[243229.956868]  [<ffffffff8162feb2>] ? panic+0x1a3/0x1e7
[243229.957854]  [<ffffffff8163f55b>] oops_end+0x12b/0x150
[243229.958834]  [<ffffffff8162f688>] no_context+0x280/0x2a3
[243229.959813]  [<ffffffff8162f71e>] __bad_area_nosemaphore+0x73/0x1ca
[243229.960798]  [<ffffffff8162f888>] bad_area_nosemaphore+0x13/0x15
[243229.961781]  [<ffffffff816422be>] __do_page_fault+0x2de/0x450
[243229.962760]  [<ffffffff81642453>] do_page_fault+0x23/0x80
[243229.963736]  [<ffffffff8163e748>] page_fault+0x28/0x30
[243229.964718]  [<ffffffffa0411478>] ? find_openstateowner_str_locked.isra.60+0x38/0x80 [nfsd]
[243229.965715]  [<ffffffffa041149d>] ? find_openstateowner_str_locked.isra.60+0x5d/0x80 [nfsd]
[243229.966695]  [<ffffffffa0416051>] nfsd4_process_open1+0x101/0x360 [nfsd]
[243229.967687]  [<ffffffffa0405cd9>] nfsd4_open+0xe9/0x850 [nfsd]
[243229.968672]  [<ffffffffa0406917>] nfsd4_proc_compound+0x4d7/0x7f0 [nfsd]
[243229.969653]  [<ffffffffa03f212b>] nfsd_dispatch+0xbb/0x200 [nfsd]
[243229.970635]  [<ffffffffa02d8183>] svc_process_common+0x453/0x6f0 [sunrpc]
[243229.971605]  [<ffffffffa02d8523>] svc_process+0x103/0x170 [sunrpc]
[243229.972544]  [<ffffffffa03f1ab7>] nfsd+0xe7/0x150 [nfsd]
[243229.973456]  [<ffffffffa03f19d0>] ? nfsd_destroy+0x80/0x80 [nfsd]
[243229.974344]  [<ffffffff810a5b2f>] kthread+0xcf/0xe0
[243229.975200]  [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[243229.976038]  [<ffffffff81646b98>] ret_from_fork+0x58/0x90
[243229.976849]  [<ffffffff810a5a60>] ? kthread_create_on_node+0x140/0x140
[243229.977638] ---[ end trace ea0c6327415cf4d3 ]---

I will compress and upload the entire capture.

Regards,

Rik

Created attachment 1192454 [details]
netconsole log of another crash - part 1/2

Created attachment 1192455 [details]
netconsole log of another crash - part 2/2

(In reply to Jeff Layton from comment #3)
> The third stack trace is probably the problem that was fixed by
> 3fcbbd244ed1d20dc0eb7d48d729503992fa9b7d upstream, or maybe a few of the
> other patches that went in around that time. I think Bruce has backported
> that, so you may want to try a more recent rhel7 kernel, as that's a clear
> memory corruptor.

That patch was already in 3.10.0-325.

(In reply to Jeff Layton from comment #3)
> I think this is actually several different bugs. The first WARN is
> interesting, but harmless.

Well, it means we've got no read open at a point when we definitely should have one....

I wonder if this might be Oleg's 5cc1fb2a093e and/or feb9dad52092.  Those aren't backported yet.  I can build an rpm with those and some other more recent upstream bugfixes, though I'm not sure how to get that to Rik for testing.

See also bug 1369600.  Possibly not strictly a dup since you may be dealing with more than one problem here.

Rik, do you mind if I open this bug to the public?

(In reply to J. Bruce Fields from comment #9)

> 
> Rik, do you mind if I open this bug to the public?

No problem, you can open it to the public.

Rik

Ahh sorry I missed the comments on this earlier this week...

The "unrecognized reply" just means that the kernel got a reply for an XID that it couldn't find. Often that means that the reply stream is misaligned in some fashion.

Hmm...maybe when we get something like that, we ought to close the connection? Getting a reply for a bogus XID would seem to be an indicator that something is out of whack there.

(In reply to J. Bruce Fields from comment #8)
> (In reply to Jeff Layton from comment #3)
> > I think this is actually several different bugs. The first WARN is
> > interesting, but harmless.
> 
> Well, it means we've got no read open at a point when we definitely should
> have one....
> 
> I wonder if this might be Oleg's 5cc1fb2a093e and/or feb9dad52092.  Those
> aren't backported yet.  I can build an rpm with those and some other more
> recent upstream bugfixes, though I'm not sure how to get that to Rik for
> testing.

Oh right. I had forgotten about that -- yeah that does seem like it could be what's needed.

Hi,

We've disabled NFS 4.1 and 4.2 on the server (so only 4.0 is used now), and the system has been up for 9 days now (which is a new record for this system).

We do still see a lot (16104243 on Aug 27) of the "receive_cb_reply: Got unrecognized reply: calldir 0x1 xpt_bc_xprt ffff88120a983000 xid 0598188f" messages.

Should be commits mentioned (5cc1fb2a093e and/or feb9dad52092) fix this issue? I will see if they apply cleanly to the 3.10.0-327.28.2.el7.x86_64 kernel.

Regards,

Rik

Hi,

It seems the two patches depend on other commits for the 3.10.0-327.28.3.el7.x86_64 kernel.

I was unable to quickly determine which commits are probably missing.

Rik

(In reply to Rik Theys from comment #14)
> We've disabled NFS 4.1 and 4.2 on the server (so only 4.0 is used now), and
> the system has been up for 9 days now (which is a new record for this
> system).

I stand corrected. The 4.1 and 4.2 was only disabled last Friday so the system has only been running without those versions for 3 days.

The system was not rebooted after disabling 4.1 and 4.2. Could that explain why the receive_cb_reply messages keep coming?

Rik

(In reply to Rik Theys from comment #16)
> (In reply to Rik Theys from comment #14)
> > We've disabled NFS 4.1 and 4.2 on the server (so only 4.0 is used now), and
> > the system has been up for 9 days now (which is a new record for this
> > system).
> 
> I stand corrected. The 4.1 and 4.2 was only disabled last Friday so the
> system has only been running without those versions for 3 days.
> 
> The system was not rebooted after disabling 4.1 and 4.2. Could that explain
> why the receive_cb_reply messages keep coming?

You'd need to at least restart the nfs server to for the change to take effect.

Also, I'm not sure off the top of my head whether 4.1/4.2 clients will deal well with the case of a server that reboots lacking support for the protocol version they were using before, so unmounting from the client and then remounting may be required.

(In reply to J. Bruce Fields from comment #17)
> You'd need to at least restart the nfs server to for the change to take
> effect.
> 
> Also, I'm not sure off the top of my head whether 4.1/4.2 clients will deal
> well with the case of a server that reboots lacking support for the protocol
> version they were using before, so unmounting from the client and then
> remounting may be required.

Yes, just checked this, and clients just error out with "protocol not supported" on any attempt to use the mountpoint.

You can also check /proc/fs/nfsd/versions to see if the change really took effect.

Hi,

(In reply to J. Bruce Fields from comment #18)
> (In reply to J. Bruce Fields from comment #17)
> > You'd need to at least restart the nfs server to for the change to take
> > effect.
> > 
> > Also, I'm not sure off the top of my head whether 4.1/4.2 clients will deal
> > well with the case of a server that reboots lacking support for the protocol
> > version they were using before, so unmounting from the client and then
> > remounting may be required.
> 
> Yes, just checked this, and clients just error out with "protocol not
> supported" on any attempt to use the mountpoint.
> 
> You can also check /proc/fs/nfsd/versions to see if the change really took
> effect.

You're right. That file shows 4.1 and 4.2 are still enabled. Strange that the box hasn't crashed then (up for 23 days now).

Could this bug be related to the following (client side) bug?
https://bugzilla.redhat.com/show_bug.cgi?id=1371237

Regards,

Rik

(In reply to Rik Theys from comment #19)
> Could this bug be related to the following (client side) bug?
> https://bugzilla.redhat.com/show_bug.cgi?id=1371237

If any of your clients fall into the range affected by that bug, then, sure, I can imagine that might make it more likely to hit some race in the server.

Of course, no behavior from the client, however bad, should cause the server to crash, so there's some server bug here regardless.

(In reply to J. Bruce Fields from comment #8)
> I wonder if this might be Oleg's 5cc1fb2a093e and/or feb9dad52092.  Those
> aren't backported yet.  I can build an rpm with those and some other more
> recent upstream bugfixes, though I'm not sure how to get that to Rik for
> testing.

And it sounds like Rik's having trouble reproducing.

But I think we should apply those two patches regardless, as they may help, and are for serious problems that others managed to hit:

feb9dad5209280085d5b0c094fa67e7a8d75c81a "nfsd: Always lock state exclusively."
5cc1fb2a093e254b656c64ff24b0b76bed1d34d9 "nfsd: Extend the mutex holding region around in nfsd4_process_open2()"

And while we're at it, rhel7 is missing three more upstream fixes for state-related races that we should also apply:

885848186fbc2d1d8fb6d2fdc2156638ae289a46 "nfsd: Close race between nfsd4_release_lockowner and nfsd4_lock"
42691398be08bd1fe99326911a0aa31f2c041d53 "nfsd: Fix race between FREE_STATEID and LOCK"
dd257933fa4b9fea66a1195f8a15111029810abc "nfsd: don't return an unhashed lock stateid after taking mutex"

Can we have a QE ack for this one? Bruce, do you have a way to test this?

Hi,

Will all the required patches be part of RHEL 7.3, which is now in beta?

Regards,

Rik

Patch(es) committed on kernel repository and an interim kernel build is undergoing testing

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

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

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://access.redhat.com/errata/RHSA-2017:1842

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://access.redhat.com/errata/RHSA-2017:1842