WARNING: CPU: 1 PID: 1 at net/core/netpoll.c:370 netpoll_send_skb+0x1fc/0x20c at boot when netconsole is enabled (kernel v6.9-rc5, v6.8.7, sungem, PowerMac G4 DP)

Mon May 6 07:27:13 AEST 2024

On Mon, 29 Apr 2024 18:36:30 -0700
Jakub Kicinski <kuba at kernel.org> wrote:

> On Sun, 28 Apr 2024 12:53:06 +0200 Erhard Furtner wrote:
> > With netconsole enabled I get this "WARNING: CPU: 1 PID: 1 at
> > net/core/netpoll.c:370 netpoll_send_skb+0x1fc/0x20c" and "WARNING:
> > CPU: 1 PID: 1 at kernel/locking/irqflag-debug.c:10
> > warn_bogus_irq_restore+0x30/0x44" at boot on my PowerMac G4 DP.
> > Happens more often than not (6-7 out of 10 times booting):  
> 
> Could you try with LOCKDEP enabled?
> I wonder if irqs_disabled() behaves differently than we expect.

Ok, after a few tries I got a "BUG: spinlock wrong CPU on CPU#0, swapper/0/1" LOCKDEP hit. But this does not happen every time when I get the netpoll_send WARNING:

[...]
printk: legacy console [netcon0] enabled
------------[ cut here ]------------
netpoll_send_skb_on_dev(): eth0 enabled interrupts in poll (gem_start_xmit+0x0/0x378)
WARNING: CPU: 0 PID: 1 at net/core/netpoll.c:370 netpoll_send_skb+0x1fc/0x20c
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 6.9.0-rc6-PMacG4 #4
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
NIP:  c06c1198 LR: c06c1198 CTR: 00000000
REGS: f1021b20 TRAP: 0700   Not tainted  (6.9.0-rc6-PMacG4)
MSR:  02029032 <VEC,EE,ME,IR,DR,RI>  CR: 24004222  XER: 00000000

GPR00: c06c1198 f1021be0 c15ab6e0 00000055 5f96410c 1bc90275 f1021b1c 0000001a 
GPR08: 2e045000 00000000 c0d63998 f1021be0 24004222 00000000 c0d63a58 00000001 
GPR16: 00009032 c00a0000 00000000 c009d69c 00000000 00000001 c22ccd34 c0ff485a 
GPR24: 00000000 00001032 c2139c00 c22ccd34 00000041 c283a560 c1581f00 c2481000 
NIP [c06c1198] netpoll_send_skb+0x1fc/0x20c
LR [c06c1198] netpoll_send_skb+0x1fc/0x20c
Call Trace:
[f1021be0] [c06c1198] netpoll_send_skb+0x1fc/0x20c (unreliable)
[f1021c10] [c05da3b8] write_msg+0x10c/0x120
[f1021c50] [c009d6d4] console_flush_all+0x244/0x330
[f1021cd0] [c009d834] console_unlock+0x74/0x124
[f1021d20] [c009e7e0] vprintk_emit+0x1fc/0x204
[f1021d50] [c009a6b4] _printk+0x6c/0x74
[f1021da0] [c009e13c] register_console+0x300/0x490
[f1021de0] [c0c486d8] init_netconsole+0xc8/0x498
[f1021e50] [c0007c08] do_one_initcall+0x84/0x294
[f1021ec0] [c0c03e70] kernel_init_freeable+0x378/0x470
[f1021f10] [c0007f34] kernel_init+0x24/0x138
[f1021f30] [c00152ec] ret_from_kernel_user_thread+0x10/0x18
--- interrupt: 0 at 0x0
Code: 39299707 89490002 2c0a0000 40a20028 39400001 3c60c0a5 389f00e0 99490002 386393d6 813f0008 80a90010 4b989fe1 <0fe00000> 2c18000e 4081fec8 4bfffea0 
---[ end trace 0000000000000000 ]---
------------[ cut here ]------------
raw_local_irq_restore() called with IRQs enabled
WARNING: CPU: 0 PID: 1 at kernel/locking/irqflag-debug.c:10 warn_bogus_irq_restore+0x30/0x44
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W          6.9.0-rc6-PMacG4 #4
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
NIP:  c07e3bf4 LR: c07e3bf4 CTR: 00000000
REGS: f1021b10 TRAP: 0700   Tainted: G        W           (6.9.0-rc6-PMacG4)
MSR:  02029032 <VEC,EE,ME,IR,DR,RI>  CR: 24004222  XER: 00000000

GPR00: c07e3bf4 f1021bd0 c15ab6e0 00000030 5f96410c 1bc90275 f1021b0c 0000001a 
GPR08: 2e045000 00000000 c0d63998 f1021bd0 24004222 00000000 c0d63a58 00000001 
GPR16: 00009032 c00a0000 00000000 c009d69c 00000000 00000001 c22ccd34 c0ff485a 
GPR24: 00000000 00001032 c2139c00 c22ccd34 00000041 c283a560 c1581f00 00000000 
NIP [c07e3bf4] warn_bogus_irq_restore+0x30/0x44
LR [c07e3bf4] warn_bogus_irq_restore+0x30/0x44
Call Trace:
[f1021bd0] [c07e3bf4] warn_bogus_irq_restore+0x30/0x44 (unreliable)
[f1021be0] [c06c1010] netpoll_send_skb+0x74/0x20c
[f1021c10] [c05da3b8] write_msg+0x10c/0x120
[f1021c50] [c009d6d4] console_flush_all+0x244/0x330
[f1021cd0] [c009d834] console_unlock+0x74/0x124
[f1021d20] [c009e7e0] vprintk_emit+0x1fc/0x204
[f1021d50] [c009a6b4] _printk+0x6c/0x74
[f1021da0] [c009e13c] register_console+0x300/0x490
[f1021de0] [c0c486d8] init_netconsole+0xc8/0x498
[f1021e50] [c0007c08] do_one_initcall+0x84/0x294
[f1021ec0] [c0c03e70] kernel_init_freeable+0x378/0x470
[f1021f10] [c0007f34] kernel_init+0x24/0x138
[f1021f30] [c00152ec] ret_from_kernel_user_thread+0x10/0x18
--- interrupt: 0 at 0x0
Code: 3d20c0dd 89499593 2c0a0000 4ca20020 9421fff0 3c60c09d 7c0802a6 39400001 386382d5 99499593 90010014 4b867585 <0fe00000> 80010014 38210010 7c0803a6 
---[ end trace 0000000000000000 ]---
BUG: spinlock wrong CPU on CPU#0, swapper/0/1
 lock: target_list_lock+0x0/0x24, .magic: dead4ead, .owner: swapper/0/1, .owner_cpu: 1
CPU: 0 PID: 1 Comm: swapper/0 Tainted: G        W          6.9.0-rc6-PMacG4 #4
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
Call Trace:
[f1021be0] [c07c2c2c] dump_stack_lvl+0x80/0xac (unreliable)
[f1021c00] [c0099474] do_raw_spin_unlock+0x90/0xb0
[f1021c30] [c07e9cf0] _raw_spin_unlock_irqrestore+0x2c/0x58
[f1021c50] [c009d6d4] console_flush_all+0x244/0x330
[f1021cd0] [c009d834] console_unlock+0x74/0x124
[f1021d20] [c009e7e0] vprintk_emit+0x1fc/0x204
[f1021d50] [c009a6b4] _printk+0x6c/0x74
[f1021da0] [c009e13c] register_console+0x300/0x490
[f1021de0] [c0c486d8] init_netconsole+0xc8/0x498
[f1021e50] [c0007c08] do_one_initcall+0x84/0x294
[f1021ec0] [c0c03e70] kernel_init_freeable+0x378/0x470
[f1021f10] [c0007f34] kernel_init+0x24/0x138
[f1021f30] [c00152ec] ret_from_kernel_user_thread+0x10/0x18
--- interrupt: 0 at 0x0
netconsole: network logging started
[...]

The G4 passed the slub, locking KUnit tests I tried. But at running dev_addr_lists_test KUnit test I get most of the time:

[...]
KTAP version 1
1..1
    KTAP version 1
    # Subtest: dev-addr-list-test
    # module: dev_addr_lists_test
    1..6

====================================
WARNING: kunit_try_catch/1778 still has locks held!
6.9.0-rc6-PMacG4 #4 Tainted: G                 N
------------------------------------
1 lock held by kunit_try_catch/1778:
 #0: c0dbfce4 (rtnl_mutex){....}-{3:3}, at: dev_addr_test_init+0xbc/0xc8 [dev_addr_lists_test]

stack backtrace:
CPU: 0 PID: 1778 Comm: kunit_try_catch Tainted: G                 N 6.9.0-rc6-PMacG4 #4
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
Call Trace:
[f39a9ef0] [c07c2c2c] dump_stack_lvl+0x80/0xac (unreliable)
[f39a9f10] [c004fe64] do_exit+0x5b4/0x834
[f39a9f60] [c006d848] kthread_complete_and_exit+0x0/0x28
[f39a9f80] [c006d870] kthread+0x0/0xe8
[f39a9fa0] [bebf2cf4] kunit_try_catch_run+0x0/0x15c [kunit]
[f39a9fc0] [c006d954] kthread+0xe4/0xe8
[f39a9ff0] [c0015304] start_kernel_thread+0x10/0x14
    ok 1 dev_addr_test_basic
    ok 2 dev_addr_test_sync_one
    ok 3 dev_addr_test_add_del
    ok 4 dev_addr_test_del_main
    ok 5 dev_addr_test_add_set
    ok 6 dev_addr_test_add_excl
# dev-addr-list-test: pass:6 fail:0 skip:0 total:6
# Totals: pass:6 fail:0 skip:0 total:6
ok 1 dev-addr-list-test
[...]

Full dmesg + kernel .config attached.

Regards,
Erhard
-------------- next part --------------
A non-text attachment was scrubbed...
Name: config_69-rc6_g4
Type: application/octet-stream
Size: 116544 bytes
Desc: not available
URL: <http://lists.ozlabs.org/pipermail/linuxppc-dev/attachments/20240505/7c2263eb/attachment-0002.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dmesg_69-rc6_g4_04
Type: application/octet-stream
Size: 47136 bytes
Desc: not available
URL: <http://lists.ozlabs.org/pipermail/linuxppc-dev/attachments/20240505/7c2263eb/attachment-0003.obj>