Re: BUG: soft lockup in kernel_init

[Petr Mladek <pmladek@suse.com>]

On Fri 2026-06-26 14:26:40, sanan.hasanou@gmail.com wrote:
> Good day, dear maintainers,
> 
> We found a bug using a modified version of syzkaller.
> 
> Kernel Branch: 7.0-rc1
> Kernel Config: <https://drive.google.com/open?id=1mAp3gxor4yGtL0ZArdrc1E7ufSn4T841>
> Unfortunately, we don't have any reproducer for this bug yet.
> Thank you!
> 
> Best regards,
> Sanan Hasanov
> 
> watchdog: BUG: soft lockup - CPU#0 stuck for 142s! [swapper/0:1]
> Modules linked in:
> irq event stamp: 1640392
> hardirqs last  enabled at (1640391): [<ffffffff819f6073>] console_trylock_spinning kernel/printk/printk.c:2032 [inline]
> hardirqs last  enabled at (1640391): [<ffffffff819f6073>] vprintk_emit+0x3b3/0x550 kernel/printk/printk.c:2478
> hardirqs last disabled at (1640392): [<ffffffff8b54d19e>] sysvec_apic_timer_interrupt+0xe/0xb0 arch/x86/kernel/apic/apic.c:1056
> softirqs last  enabled at (1640360): [<ffffffff81842680>] __do_softirq kernel/softirq.c:656 [inline]
> softirqs last  enabled at (1640360): [<ffffffff81842680>] invoke_softirq kernel/softirq.c:496 [inline]
> softirqs last  enabled at (1640360): [<ffffffff81842680>] __irq_exit_rcu+0x60/0x150 kernel/softirq.c:723
> softirqs last disabled at (1640327): [<ffffffff81842680>] __do_softirq kernel/softirq.c:656 [inline]
> softirqs last disabled at (1640327): [<ffffffff81842680>] invoke_softirq kernel/softirq.c:496 [inline]
> softirqs last disabled at (1640327): [<ffffffff81842680>] __irq_exit_rcu+0x60/0x150 kernel/softirq.c:723
> CPU: 0 UID: 0 PID: 1 Comm: swapper/0 Not tainted 7.0.0-rc1 #1 PREEMPT(full) 
> Hardware name: QEMU Ubuntu 24.04 PC v2 (i440FX + PIIX, arch_caps fix, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
> RIP: 0010:console_trylock_spinning kernel/printk/printk.c:2039 [inline]

This code is from kernel/printk/printk.c (7.0-rc1):

1080	static int console_trylock_spinning(void)
1081	{
[...]
2025		/* We spin waiting for the owner to release us */
2026		spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
2027		/* Owner will clear console_waiter on hand off */
2028		while (READ_ONCE(console_waiter))
2029			cpu_relax();
2030		spin_release(&console_owner_dep_map, _THIS_IP_);
2031
2032		printk_safe_exit_irqrestore(flags);
2033		/*
2034		 * The owner passed the console lock to us.
2035		 * Since we did not spin on console lock, annotate
2036		 * this as a trylock. Otherwise lockdep will
2037		 * complain.
2038		 */
2039		mutex_acquire(&console_lock_dep_map, 0, 1, _THIS_IP_);

The softlockup has been reported right after console_trylock_spinning()
has got the ownership and enabled interrupts again. It allowed to
process timers, including the watchdog_timer_fn().

It means that console_trylock_spinning() has been called in
task context, the interrupts were disabled inside this
function and it has been busy waiting for a long time
(~140s).

The shows that the caller has been blocked.
Unfortunately, the log does not show who blocked it.

Some hint might give a full log with with timestamps.
Could you please provide it, please?

Best Regards,
Petr

> RIP: 0010:vprintk_emit+0x453/0x550 kernel/printk/printk.c:2478
> Code: 0f 84 44 ff ff ff e8 5c d7 1f 00 fb eb 44 e8 54 d7 1f 00 e8 af 78 b5 09 4d 85 f6 74 94 e8 45 d7 1f 00 fb 48 c7 c7 20 e0 d4 8d <31> f6 ba 01 00 00 00 31 c9 41 b8 01 00 00 00 45 31 c9 53 e8 a5 35
> RSP: 0018:ffffc9000012f220 EFLAGS: 00000293
> RAX: ffffffff819f610b RBX: ffffffff819f5f85 RCX: ffff88801a6f5700
> RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff8dd4e020
> RBP: ffffc9000012f2d0 R08: ffffffff8f722db7 R09: 1ffffffff1ee45b6
> R10: dffffc0000000000 R11: fffffbfff1ee45b7 R12: 0000000000000045
> R13: 0000000000000000 R14: 0000000000000200 R15: 0000000000000000
> FS:  0000000000000000(0000) GS:ffff88809ab94000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: ffff8880186b4000 CR3: 000000000db4a000 CR4: 00000000000006f0
> Call Trace:
>  <TASK>
>  dev_vprintk_emit+0x337/0x3f0 drivers/base/core.c:4913
>  dev_printk_emit+0xe0/0x120 drivers/base/core.c:4924
>  _dev_info+0x10a/0x150 drivers/base/core.c:4982
>  cmos_do_probe+0xca4/0x1020 drivers/rtc/rtc-cmos.c:1121
>  pnp_device_probe+0x305/0x4b0 drivers/pnp/driver.c:111
>  call_driver_probe drivers/base/dd.c:-1 [inline]
>  really_probe+0x258/0xae0 drivers/base/dd.c:661
>  __driver_probe_device+0x18c/0x320 drivers/base/dd.c:803
>  driver_probe_device+0x4f/0x230 drivers/base/dd.c:833
>  __driver_attach+0x3e1/0x710 drivers/base/dd.c:1227
>  bus_for_each_dev+0x22c/0x2a0 drivers/base/bus.c:383
>  bus_add_driver+0x340/0x670 drivers/base/bus.c:715
>  driver_register+0x23a/0x310 drivers/base/driver.c:249
>  cmos_init+0x11/0x80 drivers/rtc/rtc-cmos.c:1546
>  do_one_initcall+0x1eb/0x870 init/main.c:1382
>  do_initcall_level+0x104/0x190 init/main.c:1444
>  do_initcalls+0x59/0xa0 init/main.c:1460
>  kernel_init_freeable+0x2a0/0x3e0 init/main.c:1692
>  kernel_init+0x1d/0x1c0 init/main.c:1582
>  ret_from_fork+0x507/0xb90 arch/x86/kernel/process.c:158
>  ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:245
>  </TASK>
> 
> <<<<<<<<<<<<<<< tail report >>>>>>>>>>>>>>>