Re: drivers/nx: Invalid wait context issue when rebooting

From: Vishal Chourasia
Date: Fri Oct 11 2024 - 08:34:45 EST

On Fri, Oct 11, 2024 at 09:37:27PM +1100, Michael Ellerman wrote:
> Vishal Chourasia <vishalc@xxxxxxxxxxxxx> writes:
> > Hi,
> > I am getting Invalid wait context warning printed when rebooting lpar
> >
> > kexec/61926 is trying to acquire `of_reconfig_chain.rwsem` while holding
> > spinlock `devdata_mutex`
> >
> > Note: Name of the spinlock is misleading.
>
> Oof, yeah let's rename that to devdata_spinlock at least.
>
> > In my case, I compiled a new vmlinux file and loaded it into the running
> > kernel using `kexec -l` and then hit `reboot`
> >
> > dmesg:
> > ------
> >
> > [ BUG: Invalid wait context ]
> > 6.11.0-test2-10547-g684a64bf32b6-dirty #79 Not tainted
>
> Is that v6.11 plus ~10,000 patches? O_o
>
> Ah no, 684a64bf32b6 is roughly v6.12-rc1. Maybe if you fetch tags into
> your tree you will get a more sensible version string?
>
> Could also be good to try v6.12-rc2.

[ bug: invalid wait context ]
6.12.0-rc2-invalid_wait_context-00222-g7d2910da7039 #83 not tainted
-----------------------------
kexec/11068 is trying to lock:
c000000002dbedb8 ((of_reconfig_chain).rwsem){++++}-{4:4}, at: blocking_notifier_chain_unregister+0x40/0x90
other info that might help us debug this:
context-{5:5}
4 locks held by kexec/11068:
#0: c000000002956c08 (system_transition_mutex){+.+.}-{4:4}, at: __do_sys_reboot+0xf8/0x2e0
#1: c00000000294af30 (&dev->mutex){....}-{4:4}, at: device_shutdown+0x150/0x300
#2: c000000050882138 (&dev->mutex){....}-{4:4}, at: device_shutdown+0x164/0x300
#3: c000000002dbb898 (devdata_mutex){....}-{3:3}, at: nx842_remove+0xa8/0x1bc
stack backtrace:
CPU: 6 UID: 0 PID: 11068 Comm: kexec Not tainted 6.12.0-rc2-invalid_wait_context-00222-g7d2910da7039 #83
Hardware name: IBM,9080-HEX POWER10 (architected) 0x800200 0xf000006 of:IBM,FW1060.00 (NH1060_012) hv:phyp pSeries
Call Trace:
[c00000015974b470] [c00000000130d2e4] dump_stack_lvl+0xc8/0x130 (unreliable)
[c00000015974b4b0] [c000000000312ca8] __lock_acquire+0xb68/0xf00
[c00000015974b5c0] [c000000000313130] lock_acquire.part.0+0xf0/0x2a0
[c00000015974b6e0] [c00000000138df6c] down_write+0x6c/0x1e0
[c00000015974b720] [c00000000026f060] blocking_notifier_chain_unregister+0x40/0x90
[c00000015974b750] [c000000000efe168] of_reconfig_notifier_unregister+0x28/0x40
[c00000015974b770] [c000000000ec8918] nx842_remove+0x144/0x1bc
[c00000015974b800] [c0000000001dba20] vio_bus_remove+0x50/0xc0
[c00000015974b830] [c000000000cfa2fc] device_shutdown+0x1fc/0x300
[c00000015974b8c0] [c000000000272b10] kernel_restart_prepare+0x50/0x70
[c00000015974b8e0] [c0000000003d10b8] kernel_kexec+0xa8/0x110
[c00000015974b950] [c000000000273184] __do_sys_reboot+0x214/0x2e0
[c00000015974bab0] [c000000000032708] system_call_exception+0x148/0x310
[c00000015974be50] [c00000000000cedc] system_call_vectored_common+0x15c/0x2ec
--- interrupt: 3000 at 0x7fff84557df8
NIP: 00007fff84557df8 LR: 00007fff84557df8 CTR: 0000000000000000
REGS: c00000015974be80 TRAP: 3000 Not tainted (6.12.0-rc2-invalid_wait_context-00222-g7d2910da7039)
MSR: 800000000280f033 <SF,VEC,VSX,EE,PR,FP,ME,IR,DR,RI,LE> CR: 48022484 XER: 00000000
IRQMASK: 0
GPR00: 0000000000000058 00007fffd9315af0 00007fff84667100 fffffffffee1dead
GPR04: 0000000028121969 0000000045584543 0000000000000000 0000000000000003
GPR08: 0000000000000003 0000000000000000 0000000000000000 0000000000000000
GPR12: 0000000000000000 00007fff849bb360 ffffffffffffffff 0000000000000000
GPR16: 0000000000000001 0000000000000002 0000000000000001 0000000000000001
GPR20: 000000010aa9f520 0000000000000000 0000000000000000 0000000000000001
GPR24: 000000010b3c0480 0000000000000003 0000000000000003 00007fffd9315bc0
GPR28: 000000010aa82d30 000000010aa82d28 00007fff846618d0 000000010b3c04a0
NIP [00007fff84557df8] 0x7fff84557df8
LR [00007fff84557df8] 0x7fff84557df8
--- interrupt: 3000

>
> > -----------------------------
> > kexec/61926 is trying to lock:
> > c000000002d8b590 ((of_reconfig_chain).rwsem){++++}-{4:4}, at: blocking_notifier_chain_unregister+0x44/0xa0
> > other info that might help us debug this:
> > context-{5:5}
> > 4 locks held by kexec/61926:
> > #0: c000000002926c70 (system_transition_mutex){+.+.}-{4:4}, at: __do_sys_reboot+0xf8/0x2e0
> > #1: c00000000291af30 (&dev->mutex){....}-{4:4}, at: device_shutdown+0x160/0x310
> > #2: c000000051011938 (&dev->mutex){....}-{4:4}, at: device_shutdown+0x174/0x310
> > #3: c000000002d88070 (devdata_mutex){....}-{3:3}, at: nx842_remove+0xac/0x1bc
>
> That's pretty conclusive.
>
> I don't understand why you're the first person to see this. I can't see
> that any of the relevant code has changed recently. Unless something in
> lockdep itself changed?
>
> Did you just start seeing this on recent kernels? Can you bisect?
I saw this on a recent kernel built with config lockdep enabled.
But looking at the git blame output for nx842_remove() shows that the
relevant section of the code was added 12 years ago

$ git blame -L 136,137 -L 1112,1136 drivers/crypto/nx/nx-common-pseries.c
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 136) static DEFINE_SPINLOCK(devdata_mutex);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 137)
386a966f5ce71a drivers/crypto/nx/nx-842-pseries.c (Uwe Kleine-König 2021-02-25 23:18:34 +0100 1112) static void nx842_remove(struct vio_dev *viodev)
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1113) {
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1114) struct nx842_devdata *old_devdata;
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1115) unsigned long flags;
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1116)
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1117) pr_info("Removing IBM Power 842 compression device\n");
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1118) sysfs_remove_group(&viodev->dev.kobj, &nx842_attribute_group);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1119)
8c099490fd2bd3 drivers/crypto/nx/nx-common-pseries.c (Haren Myneni 2021-06-17 13:39:08 -0700 1120) if (caps_feat)
8c099490fd2bd3 drivers/crypto/nx/nx-common-pseries.c (Haren Myneni 2021-06-17 13:39:08 -0700 1121) sysfs_remove_group(&viodev->dev.kobj, &nxcop_caps_attr_group);
8c099490fd2bd3 drivers/crypto/nx/nx-common-pseries.c (Haren Myneni 2021-06-17 13:39:08 -0700 1122)
03952d98015326 drivers/crypto/nx/nx-842-pseries.c (Dan Streetman 2015-07-22 14:26:38 -0400 1123) crypto_unregister_alg(&nx842_pseries_alg);
03952d98015326 drivers/crypto/nx/nx-842-pseries.c (Dan Streetman 2015-07-22 14:26:38 -0400 1124)
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1125) spin_lock_irqsave(&devdata_mutex, flags);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1126) old_devdata = rcu_dereference_check(devdata,
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1127) lockdep_is_held(&devdata_mutex));
1cf3d8b3d24cd3 drivers/crypto/nx/nx-842.c (Nathan Fontenot 2012-10-02 16:57:57 +0000 1128) of_reconfig_notifier_unregister(&nx842_of_nb);
7ded6e3d1bf5f8 drivers/crypto/nx/nx-842.c (Monam Agarwal 2014-03-24 01:02:42 +0530 1129) RCU_INIT_POINTER(devdata, NULL);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1130) spin_unlock_irqrestore(&devdata_mutex, flags);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1131) synchronize_rcu();
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1132) dev_set_drvdata(&viodev->dev, NULL);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1133) if (old_devdata)
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1134) kfree(old_devdata->counters);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1135) kfree(old_devdata);
0e16aafb12046e drivers/crypto/nx/nx-842.c (Seth Jennings 2012-07-19 09:42:40 -0500 1136) }

>
> > stack backtrace:
> > CPU: 2 UID: 0 PID: 61926 Comm: kexec Not tainted 6.11.0-test2-10547-g684a64bf32b6-dirty #79
> > Hardware name: IBM,9080-HEX POWER10 (architected) 0x800200 0xf000006 of:IBM,FW1060.00 (NH1060_012) hv:phyp pSeries
> > Call Trace:
> > [c0000000bb577400] [c000000001239704] dump_stack_lvl+0xc8/0x130 (unreliable)
> > [c0000000bb577440] [c000000000248398] __lock_acquire+0xb68/0xf00
> > [c0000000bb577550] [c000000000248820] lock_acquire.part.0+0xf0/0x2a0
> > [c0000000bb577670] [c00000000127faa0] down_write+0x70/0x1e0
> > [c0000000bb5776b0] [c0000000001acea4] blocking_notifier_chain_unregister+0x44/0xa0
> > [c0000000bb5776e0] [c000000000e2312c] of_reconfig_notifier_unregister+0x2c/0x40
> > [c0000000bb577700] [c000000000ded24c] nx842_remove+0x148/0x1bc
> > [c0000000bb577790] [c00000000011a114] vio_bus_remove+0x54/0xc0
> > [c0000000bb5777c0] [c000000000c1a44c] device_shutdown+0x20c/0x310
> > [c0000000bb577850] [c0000000001b0ab4] kernel_restart_prepare+0x54/0x70
> > [c0000000bb577870] [c000000000308718] kernel_kexec+0xa8/0x110
> > [c0000000bb5778e0] [c0000000001b1144] __do_sys_reboot+0x214/0x2e0
> > [c0000000bb577a40] [c000000000032f98] system_call_exception+0x148/0x310
> > [c0000000bb577e50] [c00000000000cedc] system_call_vectored_common+0x15c/0x2ec
>
> I don't see why of_reconfig_notifier_unregister() needs to be called
> with the devdata_mutext held, but I haven't looked that closely at it.
>
> So the change below might work.
>
> cheers
>
> diff --git a/drivers/crypto/nx/nx-common-pseries.c b/drivers/crypto/nx/nx-common-pseries.c
> index 35f2d0d8507e..a2050c5fb11d 100644
> --- a/drivers/crypto/nx/nx-common-pseries.c
> +++ b/drivers/crypto/nx/nx-common-pseries.c
> @@ -1122,10 +1122,11 @@ static void nx842_remove(struct vio_dev *viodev)
>
> crypto_unregister_alg(&nx842_pseries_alg);
>
> + of_reconfig_notifier_unregister(&nx842_of_nb);
> +
> spin_lock_irqsave(&devdata_mutex, flags);
> old_devdata = rcu_dereference_check(devdata,
> lockdep_is_held(&devdata_mutex));
> - of_reconfig_notifier_unregister(&nx842_of_nb);
> RCU_INIT_POINTER(devdata, NULL);
> spin_unlock_irqrestore(&devdata_mutex, flags);
> synchronize_rcu();
>
With above changes, I see another similar bug, but what's strange is
swapper does not hold any lock and still this bug is being triggered

=============================
[ BUG: Invalid wait context ]
6.12.0-rc2-fix-invalid-wait-context-00222-g7d2910da7039-dirty #84 Not tainted
-----------------------------
swapper/2/0 is trying to lock:
c000000004062128 (&xibm->lock){....}-{3:3}, at: xive_spapr_put_ipi+0xb8/0x120
other info that might help us debug this:
context-{2:2}
no locks held by swapper/2/0.
stack backtrace:
CPU: 2 UID: 0 PID: 0 Comm: swapper/2 Not tainted 6.12.0-rc2-fix-invalid-wait-context-00222-g7d2910da7039-dirty #84
Hardware name: IBM,9080-HEX POWER10 (architected) 0x800200 0xf000006 of:IBM,FW1060.00 (NH1060_012) hv:phyp pSeries
Call Trace:
[c000000004ac3420] [c00000000130d2e4] dump_stack_lvl+0xc8/0x130 (unreliable)
[c000000004ac3460] [c000000000312ca8] __lock_acquire+0xb68/0xf00
[c000000004ac3570] [c000000000313130] lock_acquire.part.0+0xf0/0x2a0
[c000000004ac3690] [c0000000013955b8] _raw_spin_lock_irqsave+0x78/0x130
kexec: waiting for cpu 2 (physical 2) to enter 2 state
[c000000004ac36d0] [c000000000194798] xive_spapr_put_ipi+0xb8/0x120
[c000000004ac3710] [c000000001383728] xive_cleanup_cpu_ipi+0xc8/0xf0
[c000000004ac3750] [c0000000013837f4] xive_teardown_cpu+0xa4/0x100
[c000000004ac3780] [c0000000001d2cc4] pseries_kexec_cpu_down+0x54/0x1e0
[c000000004ac3800] [c000000000213674] kexec_smp_down+0x124/0x1f0
[c000000004ac3890] [c0000000003c9ddc] __flush_smp_call_function_queue+0x28c/0xad0
[c000000004ac3950] [c00000000005fb64] smp_ipi_demux_relaxed+0xe4/0xf0
[c000000004ac3990] [c0000000000593d8] doorbell_exception+0x108/0x2f0
[c000000004ac3a20] [c00000000000a26c] doorbell_super_common_virt+0x28c/0x290
--- interrupt: a00 at plpar_hcall_norets_notrace+0x18/0x2c
NIP: c0000000001bee18 LR: c0000000013867a8 CTR: 0000000000000000
REGS: c000000004ac3a50 TRAP: 0a00 Not tainted (6.12.0-rc2-fix-invalid-wait-context-00222-g7d2910da7039-dirty)
MSR: 800000000280b033 <SF,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 22000242 XER: 00000001
CFAR: 0000000000000000 IRQMASK: 0
GPR00: 0000000000000000 c000000004ac3cf0 c000000001e37600 0000000000000000
GPR04: 0000000000000000 0000000000000000 0001dc4f97750361 0000000000010000
GPR08: 00000000000000c0 0000000000000080 0001dc4f97750554 0000000000000080
GPR12: 0000000000000000 c0000007fffee480 0000000000000000 0000000000000000
GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
GPR20: 0000000000000000 c000000002ebf778 0000000000000000 00000043a215d824
GPR24: 0000000000000000 c000000000ec0f80 c000000002ebf778 0000000000000000
GPR28: 0000000000000000 0000000000000001 c0000000021a2300 c0000000021a2308
NIP [c0000000001bee18] plpar_hcall_norets_notrace+0x18/0x2c
LR [c0000000013867a8] check_and_cede_processor+0x48/0x80
--- interrupt: a00
[c000000004ac3cf0] [0000000000982538] 0x982538 (unreliable)
[c000000004ac3d50] [c000000001386874] dedicated_cede_loop+0x94/0x1a0
[c000000004ac3da0] [c00000000138584c] cpuidle_enter_state+0x10c/0x8a8
[c000000004ac3e50] [c000000000ec0f80] cpuidle_enter+0x50/0x80
[c000000004ac3e90] [c0000000002ba9c8] call_cpuidle+0x48/0xa0
[c000000004ac3eb0] [c0000000002cec54] cpuidle_idle_call+0x164/0x250
[c000000004ac3f00] [c0000000002cee74] do_idle+0x134/0x1d0
[c000000004ac3f50] [c0000000002cf34c] cpu_startup_entry+0x4c/0x50
[c000000004ac3f80] [c0000000000607d0] start_secondary+0x280/0x2b0
[c000000004ac3fe0] [c00000000000e058] start_secondary_prolog+0x10/0x14