Greeting,
FYI, we noticed the following commit (built with gcc-11):
commit: 3d1f971aa81f830d2c86a781960800ebb4347601 ("random: move initialization functions out of hot pages")
https://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable-rc.git linux-4.19.y
in testcase: trinity
version: trinity-static-i386-x86_64-f93256fb_2019-08-28
with following parameters:
runtime: 300s
group: group-02
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
[ 18.287691] WARNING: possible circular locking dependency detected
[ 18.287692] 4.19.248-00165-g3d1f971aa81f #1 Not tainted
[ 18.287693] ------------------------------------------------------
[ 18.287712] stop/202 is trying to acquire lock:
[ 18.287713] (ptrval) (console_owner){..-.}, at: console_unlock (??:?)
[ 18.287717]
[ 18.287718] but task is already holding lock:
[ 18.287718] (ptrval) (&(&port->lock)->rlock){-...}, at: pty_write (pty.c:?)
[ 18.287722]
[ 18.287722] which lock already depends on the new lock.
[ 18.287723]
[ 18.287724]
[ 18.287725] the existing dependency chain (in reverse order) is:
[ 18.287725]
[ 18.287726] -> #2 (&(&port->lock)->rlock){-...}:
[ 18.287729] validate_chain+0x84a/0xe00
[ 18.287729] __lock_acquire (lockdep.c:?)
[ 18.287730] lock_acquire (??:?)
[ 18.287731] _raw_spin_lock_irqsave (??:?)
[ 18.287732] tty_port_tty_get (??:?)
[ 18.287733] tty_port_default_wakeup (tty_port.c:?)
[ 18.287734] tty_port_tty_wakeup (??:?)
[ 18.287734] uart_write_wakeup (??:?)
[ 18.287735] serial8250_tx_chars (??:?)
[ 18.287736] serial8250_handle_irq (??:?)
[ 18.287737] serial8250_default_handle_irq (8250_port.c:?)
[ 18.287738] serial8250_interrupt (8250_core.c:?)
[ 18.287738] __handle_irq_event_percpu (??:?)
[ 18.287739] handle_irq_event_percpu (??:?)
[ 18.287740] handle_irq_event (??:?)
[ 18.287741] handle_edge_irq (??:?)
[ 18.287742] handle_irq (??:?)
[ 18.287742] do_IRQ (??:?)
[ 18.287743] common_interrupt (entry_32.o:?)
[ 18.287744] _raw_spin_unlock_irqrestore (??:?)
[ 18.287745] uart_write (serial_core.c:?)
[ 18.287746] process_output_block (n_tty.c:?)
[ 18.287747] n_tty_write (n_tty.c:?)
[ 18.287747] tty_write (tty_io.c:?)
[ 18.287748] __vfs_write (??:?)
[ 18.287749] vfs_write (??:?)
[ 18.287750] ksys_write (??:?)
[ 18.287750] sys_write (??:?)
[ 18.287751] do_fast_syscall_32 (??:?)
[ 18.287752] entry_SYSENTER_32 (??:?)
[ 18.287752]
[ 18.287753] -> #1 (&port_lock_key){-.-.}:
[ 18.287756]
[ 18.287756] -> #0 (console_owner){..-.}:
[ 18.287759] check_prevs_add (lockdep.c:?)
[ 18.287760] validate_chain+0x84a/0xe00
[ 18.287761] __lock_acquire (lockdep.c:?)
[ 18.287761] lock_acquire (??:?)
[ 18.287762] console_unlock (??:?)
[ 18.287763] vprintk_emit (??:?)
[ 18.287764] vprintk_default (??:?)
[ 18.287764] vprintk_func (??:?)
[ 18.287765] printk (??:?)
[ 18.287766] get_random_u32 (??:?)
[ 18.287767] shuffle_freelist (slub.c:?)
[ 18.287767] allocate_slab (slub.c:?)
[ 18.287768] new_slab (slub.c:?)
[ 18.287769] ___slab_alloc+0x6d0/0xb20
[ 18.287770] __slab_alloc+0xd6/0x2e0
[ 18.287770] __kmalloc (??:?)
[ 18.287771] tty_buffer_alloc (tty_buffer.c:?)
[ 18.287772] __tty_buffer_request_room (tty_buffer.c:?)
[ 18.287773] tty_insert_flip_string_fixed_flag (??:?)
[ 18.287774] pty_write (pty.c:?)
[ 18.287775] process_output_block (n_tty.c:?)
[ 18.287776] n_tty_write (n_tty.c:?)
[ 18.287777] tty_write (tty_io.c:?)
[ 18.287778] __vfs_write (??:?)
[ 18.287779] vfs_write (??:?)
[ 18.287780] ksys_write (??:?)
[ 18.287780] sys_write (??:?)
[ 18.287781] do_fast_syscall_32 (??:?)
[ 18.287782] entry_SYSENTER_32 (??:?)
[ 18.287783]
[ 18.287783] other info that might help us debug this:
[ 18.287784]
[ 18.287785] Chain exists of:
[ 18.287785] console_owner --> &port_lock_key --> &(&port->lock)->rlock
[ 18.287789]
[ 18.287790] Possible unsafe locking scenario:
[ 18.287790]
[ 18.287791] CPU0 CPU1
[ 18.287792] ---- ----
[ 18.287792] lock(&(&port->lock)->rlock);
[ 18.287794] lock(&port_lock_key);
[ 18.287814] lock(&(&port->lock)->rlock);
[ 18.287815] lock(console_owner);
[ 18.287817]
[ 18.287818] *** DEADLOCK ***
[ 18.287818]
[ 18.287819] 6 locks held by stop/202:
[ 18.287820] #0: (ptrval) (&tty->ldisc_sem){++++}, at: ldsem_down_read (??:?)
[ 18.287823] #1: (ptrval) (&tty->atomic_write_lock){+.+.}, at: tty_write_lock (tty_io.c:?)
[ 18.287826] #2: (ptrval) (&o_tty->termios_rwsem/1){++++}, at: n_tty_write (n_tty.c:?)
[ 18.287830] #3: (ptrval) (&ldata->output_lock){+.+.}, at: process_output_block (n_tty.c:?)
[ 18.287834] #4: (ptrval) (&(&port->lock)->rlock){-...}, at: pty_write (pty.c:?)
[ 18.287838] #5: (ptrval) (console_lock){+.+.}, at: console_trylock_spinning (printk.c:?)
[ 18.287841]
[ 18.287842] stack backtrace:
[ 18.287843] CPU: 0 PID: 202 Comm: stop Not tainted 4.19.248-00165-g3d1f971aa81f #1
[ 18.287843] Call Trace:
[ 18.287844] dump_stack (??:?)
[ 18.287845] print_circular_bug.cold+0x78/0x8b
[ 18.287846] check_prev_add+0x66a/0xd20
[ 18.287847] check_prevs_add (lockdep.c:?)
[ 18.287848] validate_chain+0x84a/0xe00
[ 18.287848] __lock_acquire (lockdep.c:?)
[ 18.287849] lock_acquire (??:?)
[ 18.287850] ? console_unlock (??:?)
[ 18.287851] console_unlock (??:?)
[ 18.287851] ? console_unlock (??:?)
[ 18.287852] ? native_save_fl (??:?)
[ 18.287853] vprintk_emit (??:?)
[ 18.287854] vprintk_default (??:?)
[ 18.287855] vprintk_func (??:?)
[ 18.287855] printk (??:?)
[ 18.287856] get_random_u32 (??:?)
[ 18.287857] ? shuffle_freelist (slub.c:?)
[ 18.287858] shuffle_freelist (slub.c:?)
[ 18.287858] ? page_address (??:?)
[ 18.287859] allocate_slab (slub.c:?)
[ 18.287860] new_slab (slub.c:?)
[ 18.287861] ? pvclock_clocksource_read (??:?)
[ 18.287862] ___slab_alloc+0x6d0/0xb20
[ 18.287862] ? kvm_sched_clock_read (kvmclock.c:?)
[ 18.287863] ? __slab_alloc+0xbc/0x2e0
[ 18.287864] ? native_wbinvd (paravirt.c:?)
[ 18.287865] __slab_alloc+0xd6/0x2e0
[ 18.287865] __kmalloc (??:?)
[ 18.287866] ? __lock_acquire (lockdep.c:?)
[ 18.287867] ? tty_buffer_alloc (tty_buffer.c:?)
[ 18.287868] tty_buffer_alloc (tty_buffer.c:?)
[ 18.287869] __tty_buffer_request_room (tty_buffer.c:?)
[ 18.287869] tty_insert_flip_string_fixed_flag (??:?)
[ 18.287870] pty_write (pty.c:?)
[ 18.287871] process_output_block (n_tty.c:?)
[ 18.287872] n_tty_write (n_tty.c:?)
[ 18.287873] ? print_dl_stats (??:?)
[ 18.287874] ? n_tty_ioctl (n_tty.c:?)
[ 18.287874] tty_write (tty_io.c:?)
[ 18.287875] ? n_tty_ioctl (n_tty.c:?)
[ 18.287876] ? tty_write_unlock (tty_io.c:?)
[ 18.287877] __vfs_write (??:?)
[ 18.287877] vfs_write (??:?)
[ 18.287878] ? __fget_light (file.c:?)
[ 18.287879] ksys_write (??:?)
To reproduce:
# build kernel
cd linux
cp config-4.19.248-00165-g3d1f971aa81f .config
make HOSTCC=gcc-11 CC=gcc-11 ARCH=i386 olddefconfig prepare modules_prepare bzImage modules
make HOSTCC=gcc-11 CC=gcc-11 ARCH=i386 INSTALL_MOD_PATH=<mod-install-dir> modules_install
cd <mod-install-dir>
find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
--
0-DAY CI Kernel Test Service
https://01.org/lkp
In 2019, Sergey fixed a lockdep splat with 15341b1dd409 ("char/random:
silence a lockdep splat with printk()"), but that got reverted soon
after from 4.19 because back then it apparently caused various problems.
But the issue it was fixing is still there, and more generally, many
patches turning printk() into printk_deferred() have landed since,
making me suspect it's okay to try this out again.
This should fix the following deadlock found by the kernel test robot:
[ 18.287691] WARNING: possible circular locking dependency detected
[ 18.287692] 4.19.248-00165-g3d1f971aa81f #1 Not tainted
[ 18.287693] ------------------------------------------------------
[ 18.287712] stop/202 is trying to acquire lock:
[ 18.287713] (ptrval) (console_owner){..-.}, at: console_unlock (??:?)
[ 18.287717]
[ 18.287718] but task is already holding lock:
[ 18.287718] (ptrval) (&(&port->lock)->rlock){-...}, at: pty_write (pty.c:?)
[ 18.287722]
[ 18.287722] which lock already depends on the new lock.
[ 18.287723]
[ 18.287724]
[ 18.287725] the existing dependency chain (in reverse order) is:
[ 18.287725]
[ 18.287726] -> #2 (&(&port->lock)->rlock){-...}:
[ 18.287729] validate_chain+0x84a/0xe00
[ 18.287729] __lock_acquire (lockdep.c:?)
[ 18.287730] lock_acquire (??:?)
[ 18.287731] _raw_spin_lock_irqsave (??:?)
[ 18.287732] tty_port_tty_get (??:?)
[ 18.287733] tty_port_default_wakeup (tty_port.c:?)
[ 18.287734] tty_port_tty_wakeup (??:?)
[ 18.287734] uart_write_wakeup (??:?)
[ 18.287735] serial8250_tx_chars (??:?)
[ 18.287736] serial8250_handle_irq (??:?)
[ 18.287737] serial8250_default_handle_irq (8250_port.c:?)
[ 18.287738] serial8250_interrupt (8250_core.c:?)
[ 18.287738] __handle_irq_event_percpu (??:?)
[ 18.287739] handle_irq_event_percpu (??:?)
[ 18.287740] handle_irq_event (??:?)
[ 18.287741] handle_edge_irq (??:?)
[ 18.287742] handle_irq (??:?)
[ 18.287742] do_IRQ (??:?)
[ 18.287743] common_interrupt (entry_32.o:?)
[ 18.287744] _raw_spin_unlock_irqrestore (??:?)
[ 18.287745] uart_write (serial_core.c:?)
[ 18.287746] process_output_block (n_tty.c:?)
[ 18.287747] n_tty_write (n_tty.c:?)
[ 18.287747] tty_write (tty_io.c:?)
[ 18.287748] __vfs_write (??:?)
[ 18.287749] vfs_write (??:?)
[ 18.287750] ksys_write (??:?)
[ 18.287750] sys_write (??:?)
[ 18.287751] do_fast_syscall_32 (??:?)
[ 18.287752] entry_SYSENTER_32 (??:?)
[ 18.287752]
[ 18.287753] -> #1 (&port_lock_key){-.-.}:
[ 18.287756]
[ 18.287756] -> #0 (console_owner){..-.}:
[ 18.287759] check_prevs_add (lockdep.c:?)
[ 18.287760] validate_chain+0x84a/0xe00
[ 18.287761] __lock_acquire (lockdep.c:?)
[ 18.287761] lock_acquire (??:?)
[ 18.287762] console_unlock (??:?)
[ 18.287763] vprintk_emit (??:?)
[ 18.287764] vprintk_default (??:?)
[ 18.287764] vprintk_func (??:?)
[ 18.287765] printk (??:?)
[ 18.287766] get_random_u32 (??:?)
[ 18.287767] shuffle_freelist (slub.c:?)
[ 18.287767] allocate_slab (slub.c:?)
[ 18.287768] new_slab (slub.c:?)
[ 18.287769] ___slab_alloc+0x6d0/0xb20
[ 18.287770] __slab_alloc+0xd6/0x2e0
[ 18.287770] __kmalloc (??:?)
[ 18.287771] tty_buffer_alloc (tty_buffer.c:?)
[ 18.287772] __tty_buffer_request_room (tty_buffer.c:?)
[ 18.287773] tty_insert_flip_string_fixed_flag (??:?)
[ 18.287774] pty_write (pty.c:?)
[ 18.287775] process_output_block (n_tty.c:?)
[ 18.287776] n_tty_write (n_tty.c:?)
[ 18.287777] tty_write (tty_io.c:?)
[ 18.287778] __vfs_write (??:?)
[ 18.287779] vfs_write (??:?)
[ 18.287780] ksys_write (??:?)
[ 18.287780] sys_write (??:?)
[ 18.287781] do_fast_syscall_32 (??:?)
[ 18.287782] entry_SYSENTER_32 (??:?)
[ 18.287783]
[ 18.287783] other info that might help us debug this:
[ 18.287784]
[ 18.287785] Chain exists of:
[ 18.287785] console_owner --> &port_lock_key --> &(&port->lock)->rlock
[ 18.287789]
[ 18.287790] Possible unsafe locking scenario:
[ 18.287790]
[ 18.287791] CPU0 CPU1
[ 18.287792] ---- ----
[ 18.287792] lock(&(&port->lock)->rlock);
[ 18.287794] lock(&port_lock_key);
[ 18.287814] lock(&(&port->lock)->rlock);
[ 18.287815] lock(console_owner);
[ 18.287817]
[ 18.287818] *** DEADLOCK ***
[ 18.287818]
[ 18.287819] 6 locks held by stop/202:
[ 18.287820] #0: (ptrval) (&tty->ldisc_sem){++++}, at: ldsem_down_read (??:?)
[ 18.287823] #1: (ptrval) (&tty->atomic_write_lock){+.+.}, at: tty_write_lock (tty_io.c:?)
[ 18.287826] #2: (ptrval) (&o_tty->termios_rwsem/1){++++}, at: n_tty_write (n_tty.c:?)
[ 18.287830] #3: (ptrval) (&ldata->output_lock){+.+.}, at: process_output_block (n_tty.c:?)
[ 18.287834] #4: (ptrval) (&(&port->lock)->rlock){-...}, at: pty_write (pty.c:?)
[ 18.287838] #5: (ptrval) (console_lock){+.+.}, at: console_trylock_spinning (printk.c:?)
[ 18.287841]
[ 18.287842] stack backtrace:
[ 18.287843] CPU: 0 PID: 202 Comm: stop Not tainted 4.19.248-00165-g3d1f971aa81f #1
[ 18.287843] Call Trace:
[ 18.287844] dump_stack (??:?)
[ 18.287845] print_circular_bug.cold+0x78/0x8b
[ 18.287846] check_prev_add+0x66a/0xd20
[ 18.287847] check_prevs_add (lockdep.c:?)
[ 18.287848] validate_chain+0x84a/0xe00
[ 18.287848] __lock_acquire (lockdep.c:?)
[ 18.287849] lock_acquire (??:?)
[ 18.287850] ? console_unlock (??:?)
[ 18.287851] console_unlock (??:?)
[ 18.287851] ? console_unlock (??:?)
[ 18.287852] ? native_save_fl (??:?)
[ 18.287853] vprintk_emit (??:?)
[ 18.287854] vprintk_default (??:?)
[ 18.287855] vprintk_func (??:?)
[ 18.287855] printk (??:?)
[ 18.287856] get_random_u32 (??:?)
[ 18.287857] ? shuffle_freelist (slub.c:?)
[ 18.287858] shuffle_freelist (slub.c:?)
[ 18.287858] ? page_address (??:?)
[ 18.287859] allocate_slab (slub.c:?)
[ 18.287860] new_slab (slub.c:?)
[ 18.287861] ? pvclock_clocksource_read (??:?)
[ 18.287862] ___slab_alloc+0x6d0/0xb20
[ 18.287862] ? kvm_sched_clock_read (kvmclock.c:?)
[ 18.287863] ? __slab_alloc+0xbc/0x2e0
[ 18.287864] ? native_wbinvd (paravirt.c:?)
[ 18.287865] __slab_alloc+0xd6/0x2e0
[ 18.287865] __kmalloc (??:?)
[ 18.287866] ? __lock_acquire (lockdep.c:?)
[ 18.287867] ? tty_buffer_alloc (tty_buffer.c:?)
[ 18.287868] tty_buffer_alloc (tty_buffer.c:?)
[ 18.287869] __tty_buffer_request_room (tty_buffer.c:?)
[ 18.287869] tty_insert_flip_string_fixed_flag (??:?)
[ 18.287870] pty_write (pty.c:?)
[ 18.287871] process_output_block (n_tty.c:?)
[ 18.287872] n_tty_write (n_tty.c:?)
[ 18.287873] ? print_dl_stats (??:?)
[ 18.287874] ? n_tty_ioctl (n_tty.c:?)
[ 18.287874] tty_write (tty_io.c:?)
[ 18.287875] ? n_tty_ioctl (n_tty.c:?)
[ 18.287876] ? tty_write_unlock (tty_io.c:?)
[ 18.287877] __vfs_write (??:?)
[ 18.287877] vfs_write (??:?)
[ 18.287878] ? __fget_light (file.c:?)
[ 18.287879] ksys_write (??:?)
Cc: Sergey Senozhatsky <[email protected]>
Cc: Qian Cai <[email protected]>
Cc: Lech Perczak <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Theodore Ts'o <[email protected]>
Cc: Sasha Levin <[email protected]>
Cc: Petr Mladek <[email protected]>
Cc: John Ogness <[email protected]>
Reported-by: kernel test robot <[email protected]>
Link: https://lore.kernel.org/lkml/Ytz+lo4zRQYG3JUR@xsang-OptiPlex-9020
Signed-off-by: Jason A. Donenfeld <[email protected]>
---
drivers/char/random.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/drivers/char/random.c b/drivers/char/random.c
index bac4dc501dc4..2be38780a7f7 100644
--- a/drivers/char/random.c
+++ b/drivers/char/random.c
@@ -183,8 +183,8 @@ static void __cold process_random_ready_list(void)
#define warn_unseeded_randomness() \
if (IS_ENABLED(CONFIG_WARN_ALL_UNSEEDED_RANDOM) && !crng_ready()) \
- pr_notice("%s called from %pS with crng_init=%d\n", \
- __func__, (void *)_RET_IP_, crng_init)
+ printk_deferred(KERN_NOTICE "random: %s called from %pS with crng_init=%d\n", \
+ __func__, (void *)_RET_IP_, crng_init)
/*********************************************************************
--
2.35.1