syzbot


possible deadlock in console_trylock_spinning (2)

Status: upstream: reported C repro on 2023/11/29 03:09
Bug presence: origin:lts-only
[Documentation on labels]
Reported-by: syzbot+dc57c1cfb6ac07a3c0d2@syzkaller.appspotmail.com
First crash: 154d, last: 1d11h
Fix commit to backport (bisect log) :
tree: upstream
commit 09c5ba0aa2fcfdadb17d045c3ee6f86d69270df7
Author: John Ogness <john.ogness@linutronix.de>
Date: Thu Apr 21 21:22:48 2022 +0000

  printk: add kthread console printers

  
Bug presence (2)
Date Name Commit Repro Result
2024/01/22 linux-5.15.y (ToT) ddcaf4999061 C [report] possible deadlock in console_trylock_spinning
2024/01/22 upstream (ToT) 6613476e225e C Didn't crash
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream possible deadlock in console_trylock_spinning serial C done inconclusive 168 716d 1776d 0/26 auto-obsoleted due to no activity on 2022/10/10 16:31
linux-5.15 possible deadlock in console_trylock_spinning 4 255d 372d 0/3 auto-obsoleted due to no activity on 2023/11/27 19:44
Fix bisection attempts (1)
Created Duration User Patch Repo Result
2024/01/22 12:11 3h47m fix candidate upstream job log (1)

Sample crash report:
FAULT_INJECTION: forcing a failure.
name failslab, interval 1, probability 0, space 0, times 1
======================================================
WARNING: possible circular locking dependency detected
5.15.147-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor142/3499 is trying to acquire lock:
ffffffff8c913da0 (console_owner){-...}-{0:0}, at: console_trylock_spinning+0x185/0x3f0 kernel/printk/printk.c:1879

but task is already holding lock:
ffff88801d7ec158 (&port->lock){-...}-{2:2}, at: tty_insert_flip_string_and_push_buffer+0x3a/0x390 drivers/tty/tty_buffer.c:585

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&port->lock){-...}-{2:2}:
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
       tty_port_tty_get drivers/tty/tty_port.c:289 [inline]
       tty_port_default_wakeup+0x21/0x100 drivers/tty/tty_port.c:48
       serial8250_tx_chars+0x60d/0x800 drivers/tty/serial/8250/8250_port.c:1848
       serial8250_handle_irq+0x505/0x600 drivers/tty/serial/8250/8250_port.c:1944
       serial8250_default_handle_irq+0xc8/0x1e0 drivers/tty/serial/8250/8250_port.c:1961
       serial8250_interrupt+0xa1/0x1e0 drivers/tty/serial/8250/8250_core.c:127
       __handle_irq_event_percpu+0x292/0xa70 kernel/irq/handle.c:156
       handle_irq_event_percpu kernel/irq/handle.c:196 [inline]
       handle_irq_event+0xff/0x2b0 kernel/irq/handle.c:213
       handle_edge_irq+0x245/0xbf0 kernel/irq/chip.c:822
       generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
       handle_irq arch/x86/kernel/irq.c:231 [inline]
       __common_interrupt+0xd7/0x1f0 arch/x86/kernel/irq.c:250
       common_interrupt+0x9f/0xc0 arch/x86/kernel/irq.c:240
       asm_common_interrupt+0x22/0x40 arch/x86/include/asm/idtentry.h:629
       __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:161 [inline]
       _raw_spin_unlock_irqrestore+0xd4/0x130 kernel/locking/spinlock.c:194
       spin_unlock_irqrestore include/linux/spinlock.h:418 [inline]
       uart_write+0x6af/0x930 drivers/tty/serial/serial_core.c:590
       process_output_block drivers/tty/n_tty.c:592 [inline]
       n_tty_write+0xd7e/0x1280 drivers/tty/n_tty.c:2339
       do_tty_write drivers/tty/tty_io.c:1038 [inline]
       file_tty_write+0x561/0x920 drivers/tty/tty_io.c:1110
       call_write_iter include/linux/fs.h:2146 [inline]
       new_sync_write fs/read_write.c:507 [inline]
       vfs_write+0xacf/0xe50 fs/read_write.c:594
       ksys_write+0x1a2/0x2c0 fs/read_write.c:647
       do_syscall_x64 arch/x86/entry/common.c:50 [inline]
       do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:80
       entry_SYSCALL_64_after_hwframe+0x61/0xcb

-> #1 (&port_lock_key){-...}-{2:2}:
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0xd1/0x120 kernel/locking/spinlock.c:162
       serial8250_console_write+0x19d/0x1180 drivers/tty/serial/8250/8250_port.c:3374
       console_unlock+0xced/0x12b0 kernel/printk/printk.c:2738
       vprintk_emit+0xbf/0x150 kernel/printk/printk.c:2268
       _printk+0xd1/0x111 kernel/printk/printk.c:2293
       register_console+0x68c/0x970 kernel/printk/printk.c:3078
       univ8250_console_init+0x41/0x43 drivers/tty/serial/8250/8250_core.c:690
       console_init+0x18c/0x652 kernel/printk/printk.c:3178
       start_kernel+0x301/0x535 init/main.c:1073
       secondary_startup_64_no_verify+0xb1/0xbb

-> #0 (console_owner){-...}-{0:0}:
       check_prev_add kernel/locking/lockdep.c:3053 [inline]
       check_prevs_add kernel/locking/lockdep.c:3172 [inline]
       validate_chain+0x1649/0x5930 kernel/locking/lockdep.c:3788
       __lock_acquire+0x1295/0x1ff0 kernel/locking/lockdep.c:5012
       lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
       console_trylock_spinning+0x1a5/0x3f0 kernel/printk/printk.c:1896
       vprintk_emit+0xa6/0x150 kernel/printk/printk.c:2267
       _printk+0xd1/0x111 kernel/printk/printk.c:2293
       fail_dump lib/fault-inject.c:45 [inline]
       should_fail+0x36c/0x4c0 lib/fault-inject.c:146
       should_failslab+0x5/0x20 mm/slab_common.c:1337
       slab_pre_alloc_hook+0x53/0xc0 mm/slab.h:494
       slab_alloc_node mm/slub.c:3134 [inline]
       slab_alloc mm/slub.c:3228 [inline]
       __kmalloc+0x6e/0x300 mm/slub.c:4403
       kmalloc include/linux/slab.h:596 [inline]
       tty_buffer_alloc drivers/tty/tty_buffer.c:177 [inline]
       __tty_buffer_request_room+0x1ef/0x500 drivers/tty/tty_buffer.c:276
       tty_insert_flip_string_fixed_flag drivers/tty/tty_buffer.c:322 [inline]
       tty_insert_flip_string include/linux/tty_flip.h:41 [inline]
       tty_insert_flip_string_and_push_buffer+0x7c/0x390 drivers/tty/tty_buffer.c:586
       n_tty_write+0x63c/0x1280 drivers/tty/n_tty.c:2362
       do_tty_write drivers/tty/tty_io.c:1038 [inline]
       file_tty_write+0x561/0x920 drivers/tty/tty_io.c:1110
       do_iter_readv_writev+0x594/0x7a0
       do_iter_write+0x1ea/0x760 fs/read_write.c:855
       iter_file_splice_write+0x806/0xfa0 fs/splice.c:689
       do_splice_from fs/splice.c:767 [inline]
       direct_splice_actor+0xe3/0x1c0 fs/splice.c:936
       splice_direct_to_actor+0x500/0xc10 fs/splice.c:891
       do_splice_direct+0x285/0x3d0 fs/splice.c:979
       do_sendfile+0x625/0xff0 fs/read_write.c:1249
       __do_sys_sendfile64 fs/read_write.c:1317 [inline]
       __se_sys_sendfile64+0x178/0x1e0 fs/read_write.c:1303
       do_syscall_x64 arch/x86/entry/common.c:50 [inline]
       do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:80
       entry_SYSCALL_64_after_hwframe+0x61/0xcb

other info that might help us debug this:

Chain exists of:
  console_owner --> &port_lock_key --> &port->lock

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&port->lock);
                               lock(&port_lock_key);
                               lock(&port->lock);
  lock(console_owner);

 *** DEADLOCK ***

5 locks held by syz-executor142/3499:
 #0: ffff8881474c6098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x21/0x70 drivers/tty/tty_ldisc.c:252
 #1: ffff8881474c6130 (&tty->atomic_write_lock){+.+.}-{3:3}, at: tty_write_lock drivers/tty/tty_io.c:961 [inline]
 #1: ffff8881474c6130 (&tty->atomic_write_lock){+.+.}-{3:3}, at: do_tty_write drivers/tty/tty_io.c:984 [inline]
 #1: ffff8881474c6130 (&tty->atomic_write_lock){+.+.}-{3:3}, at: file_tty_write+0x24f/0x920 drivers/tty/tty_io.c:1110
 #2: ffff8881474c62e8 (&tty->termios_rwsem){++++}-{3:3}, at: n_tty_write+0x252/0x1280 drivers/tty/n_tty.c:2322
 #3: ffffc900010e8378 (&ldata->output_lock){+.+.}-{3:3}, at: n_tty_write+0x5ee/0x1280 drivers/tty/n_tty.c:2361
 #4: ffff88801d7ec158 (&port->lock){-...}-{2:2}, at: tty_insert_flip_string_and_push_buffer+0x3a/0x390 drivers/tty/tty_buffer.c:585

stack backtrace:
CPU: 1 PID: 3499 Comm: syz-executor142 Not tainted 5.15.147-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 11/17/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2cb lib/dump_stack.c:106
 check_noncircular+0x2f8/0x3b0 kernel/locking/lockdep.c:2133
 check_prev_add kernel/locking/lockdep.c:3053 [inline]
 check_prevs_add kernel/locking/lockdep.c:3172 [inline]
 validate_chain+0x1649/0x5930 kernel/locking/lockdep.c:3788
 __lock_acquire+0x1295/0x1ff0 kernel/locking/lockdep.c:5012
 lock_acquire+0x1db/0x4f0 kernel/locking/lockdep.c:5623
 console_trylock_spinning+0x1a5/0x3f0 kernel/printk/printk.c:1896
 vprintk_emit+0xa6/0x150 kernel/printk/printk.c:2267
 _printk+0xd1/0x111 kernel/printk/printk.c:2293
 fail_dump lib/fault-inject.c:45 [inline]
 should_fail+0x36c/0x4c0 lib/fault-inject.c:146
 should_failslab+0x5/0x20 mm/slab_common.c:1337
 slab_pre_alloc_hook+0x53/0xc0 mm/slab.h:494
 slab_alloc_node mm/slub.c:3134 [inline]
 slab_alloc mm/slub.c:3228 [inline]
 __kmalloc+0x6e/0x300 mm/slub.c:4403
 kmalloc include/linux/slab.h:596 [inline]
 tty_buffer_alloc drivers/tty/tty_buffer.c:177 [inline]
 __tty_buffer_request_room+0x1ef/0x500 drivers/tty/tty_buffer.c:276
 tty_insert_flip_string_fixed_flag drivers/tty/tty_buffer.c:322 [inline]
 tty_insert_flip_string include/linux/tty_flip.h:41 [inline]
 tty_insert_flip_string_and_push_buffer+0x7c/0x390 drivers/tty/tty_buffer.c:586
 n_tty_write+0x63c/0x1280 drivers/tty/n_tty.c:2362
 do_tty_write drivers/tty/tty_io.c:1038 [inline]
 file_tty_write+0x561/0x920 drivers/tty/tty_io.c:1110
 do_iter_readv_writev+0x594/0x7a0
 do_iter_write+0x1ea/0x760 fs/read_write.c:855
 iter_file_splice_write+0x806/0xfa0 fs/splice.c:689
 do_splice_from fs/splice.c:767 [inline]
 direct_splice_actor+0xe3/0x1c0 fs/splice.c:936
 splice_direct_to_actor+0x500/0xc10 fs/splice.c:891
 do_splice_direct+0x285/0x3d0 fs/splice.c:979
 do_sendfile+0x625/0xff0 fs/read_write.c:1249
 __do_sys_sendfile64 fs/read_write.c:1317 [inline]
 __se_sys_sendfile64+0x178/0x1e0 fs/read_write.c:1303
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x61/0xcb
RIP: 0033:0x7fb353f84139
Code: 48 83 c4 28 c3 e8 37 17 00 00 0f 1f 80 00 00 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffc284df168 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 00007ffc284df170 RCX: 00007fb353f84139
RDX: 0000000000000000 RSI: 0000000000000006 RDI: 0000000000000005
RBP: 0000000000000002 R08: 00007ffc284def06 R09: 00007fb353003432
R10: 0001000000201005 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffc284df3d8 R14: 0000000000000001 R15: 0000000000000001
 </TASK>
CPU: 1 PID: 3499 Comm: syz-executor142 Not tainted 5.15.147-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 11/17/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e3/0x2cb lib/dump_stack.c:106
 fail_dump lib/fault-inject.c:52 [inline]
 should_fail+0x38a/0x4c0 lib/fault-inject.c:146
 should_failslab+0x5/0x20 mm/slab_common.c:1337
 slab_pre_alloc_hook+0x53/0xc0 mm/slab.h:494
 slab_alloc_node mm/slub.c:3134 [inline]
 slab_alloc mm/slub.c:3228 [inline]
 __kmalloc+0x6e/0x300 mm/slub.c:4403
 kmalloc include/linux/slab.h:596 [inline]
 tty_buffer_alloc drivers/tty/tty_buffer.c:177 [inline]
 __tty_buffer_request_room+0x1ef/0x500 drivers/tty/tty_buffer.c:276
 tty_insert_flip_string_fixed_flag drivers/tty/tty_buffer.c:322 [inline]
 tty_insert_flip_string include/linux/tty_flip.h:41 [inline]
 tty_insert_flip_string_and_push_buffer+0x7c/0x390 drivers/tty/tty_buffer.c:586
 n_tty_write+0x63c/0x1280 drivers/tty/n_tty.c:2362
 do_tty_write drivers/tty/tty_io.c:1038 [inline]
 file_tty_write+0x561/0x920 drivers/tty/tty_io.c:1110
 do_iter_readv_writev+0x594/0x7a0
 do_iter_write+0x1ea/0x760 fs/read_write.c:855
 iter_file_splice_write+0x806/0xfa0 fs/splice.c:689
 do_splice_from fs/splice.c:767 [inline]
 direct_splice_actor+0xe3/0x1c0 fs/splice.c:936
 splice_direct_to_actor+0x500/0xc10 fs/splice.c:891
 do_splice_direct+0x285/0x3d0 fs/splice.c:979
 do_sendfile+0x625/0xff0 fs/read_write.c:1249
 __do_sys_sendfile64 fs/read_write.c:1317 [inline]
 __se_sys_sendfile64+0x178/0x1e0 fs/read_write.c:1303
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x3d/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x61/0xcb
RIP: 0033:0x7fb353f84139
Code: 48 83 c4 28 c3 e8 37 17 00 00 0f 1f 80 00 00 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffc284df168 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
RAX: fffffffffffff

Crashes (13):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2024/01/21 21:31 linux-5.15.y ddcaf4999061 9bd8dcda .config console log report syz C [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in console_trylock_spinning
2024/04/29 19:05 linux-5.15.y b925f60c6ee7 27e33c58 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in console_trylock_spinning
2024/04/16 19:53 linux-5.15.y fa3df276cd36 18f6e127 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in console_trylock_spinning
2024/04/15 14:37 linux-5.15.y fa3df276cd36 b9af7e61 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in console_trylock_spinning
2024/04/11 02:22 linux-5.15.y cdfd0a7f0139 33b9e058 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in console_trylock_spinning
2024/04/09 16:33 linux-5.15.y 9465fef4ae35 f3234354 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in console_trylock_spinning
2024/04/07 04:15 linux-5.15.y 9465fef4ae35 ca620dd8 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in console_trylock_spinning
2024/04/04 07:28 linux-5.15.y 9465fef4ae35 51c4dcff .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in console_trylock_spinning
2024/04/01 17:35 linux-5.15.y 9465fef4ae35 6baf5069 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-perf possible deadlock in console_trylock_spinning
2024/01/21 21:11 linux-5.15.y ddcaf4999061 9bd8dcda .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in console_trylock_spinning
2023/12/26 09:32 linux-5.15.y d93fa2c78854 fb427a07 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan possible deadlock in console_trylock_spinning
2023/12/01 06:44 linux-5.15.y a78d278e01b1 f819d6f7 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-arm64 possible deadlock in console_trylock_spinning
2023/11/29 03:08 linux-5.15.y a78d278e01b1 1adfb6f6 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-5-15-kasan-arm64 possible deadlock in console_trylock_spinning
* Struck through repros no longer work on HEAD.