BUG: soft lockup in kernel_init

BUG: soft lockup in kernel_init

[sanan.hasanou]

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]
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 >>>>>>>>>>>>>>>

Re: BUG: soft lockup in kernel_init

[Petr Mladek]

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 >>>>>>>>>>>>>>>

buddy softlockup detector: was: Re: BUG: soft lockup in kernel_init

[Petr Mladek]

Adding Douglas into Cc.

On Mon 2026-06-29 14:47:09, Petr Mladek wrote:
> 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.

It is pity that the softlockup could be reported only after
the given CPU gets unstuck. It might be very helpful when
the lockup might get detected and reported by another CPU
which is not blocked at the moment, using a similar
trick like the buddy hardlockup detector.

Then we would be able to trigger backtraces from all
CPUs earlier and catch the task blocking the progress.

Douglas, have you ever thought about this, please?

Best Regards,
Petr

> Some hint might give a full log with with timestamps.
> Could you please provide it, please?
> 
> > 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 >>>>>>>>>>>>>>>