Re: [PATCH v2 3/4] printk: nbcon: move printk_delay to console emiting code

[sashiko-bot@kernel.org]

Thank you for your contribution! Sashiko AI review found 4 potential issue(s) to consider:

New issues:
- [High] `printk_delay(use_atomic)` causes massive IRQ latency by busy-waiting with local interrupts disabled in `nbcon_legacy_emit_next_record()`.
- [Medium] `printk_delay()` bypasses its intended rate-limiting function when a console lock handover occurs in `console_emit_next_record()`.
- [Medium] Moving `printk_delay()` into the console flush loops incorrectly multiplies the delay by the number of active consoles.

Pre-existing issues:
- [Critical] Use-after-free of the `con` pointer in `console_flush_all()` due to an expanded race window when `printk_delay()` is called.
--

commit e90407202970d9d83dc93dd60ca58eb802e88311
Author: Andrew Murray <amurray@thegoodpenguin.co.uk>

printk: nbcon: move printk_delay to console emiting code

This commit moves the printk delay from the caller of printk to the
console emitting code. This ensures delays are observed even when
messages are emitted asynchronously to the console.

> diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
> --- a/kernel/printk/nbcon.c
> +++ b/kernel/printk/nbcon.c

[ ... ]

> @@ -1525,6 +1532,8 @@ bool nbcon_legacy_emit_next_record(struct console *con, bool *handover,
>  	}
>  
>  	progress = nbcon_emit_one(&wctxt, use_atomic);
> +	if (progress && wctxt.emitted)
> +		printk_delay(use_atomic);

[Severity: High]
Does calling printk_delay() here cause massive IRQ latency?

In nbcon_legacy_emit_next_record(), when use_atomic is true, local
interrupts are explicitly disabled via printk_safe_enter_irqsave() just
before this block:

	if (use_atomic) {
		printk_safe_enter_irqsave(flags);
		console_lock_spinning_enable();
		stop_critical_timings();
	}

Calling printk_delay(use_atomic) while IRQs are disabled will execute
late_boot_delay_msec() which busy-loops.

Could this stall the CPU with interrupts disabled for hundreds of
milliseconds per message, potentially dropping hardware interrupts or
triggering the NMI watchdog?

>  	if (use_atomic) {
>  		start_critical_timings();

[ ... ]

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c

[ ... ]

> @@ -3211,6 +3208,8 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
>  		*handover = console_lock_spinning_disable_and_check(cookie);
>  		printk_safe_exit_irqrestore(flags);
>  	}
> +	printk_delay(true);
> +

[Severity: Critical]
This isn't a bug introduced by this patch, but does the expanded delay
create a use-after-free window for the con pointer in console_flush_all()?

In console_emit_next_record(), if a lock handover occurs,
console_lock_spinning_disable_and_check() releases the SRCU read lock.
This patch inserts printk_delay(true) immediately after this lock release,
adding a multi-millisecond busy-wait delay.

During this expanded window, another CPU can unregister and free the console
because the SRCU lock is no longer held.

When console_emit_next_record() returns to console_flush_all(), it
unconditionally dereferences con->seq before checking if a handover occurred:

		if (!console_emit_next_record(con, &handover, cookie))
			continue;
		printk_seq = con->seq;

Could this massive delay guarantee a use-after-free if a console is
unregistered under contention?

[Severity: Medium]
Also regarding this delay placement, if a console lock handover occurs,
is the intended rate limiting bypassed?

When multiple CPUs attempt to print, console_lock_spinning_disable_and_check()
yields the lock to a waiting CPU before the delay begins.

The waiting CPU will immediately acquire the lock and begin printing the next
message without waiting for the first CPU's delay to finish.

Does this result in messages being emitted in an immediate burst under lock
contention, bypassing the intended pacing?

[Severity: Medium]
Additionally, does moving printk_delay() here multiply the delay by the
number of active consoles?

Previously, vprintk_emit() called printk_delay() once per message.

Because console_emit_next_record() is called sequentially for each registered
console within the for_each_console_srcu(con) loop in console_flush_all():

	for_each_console_srcu(con) {
		...
		if (!console_emit_next_record(con, &handover, cookie))
			continue;
		...
	}

Will the delay now be executed N times per message, where N is the number of
active consoles?

>  skip:
>  	return true;
>  }

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20260630-deprecate_boot_delay-v2-0-f9883d36aa4b@thegoodpenguin.co.uk?part=3