possible deadlock in tty_port_close_start

40 views
Skip to first unread message

syzbot

unread,
Feb 5, 2020, 6:51:11 PM2/5/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: b499cf4b Linux 4.19.102
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=1453b911e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=7ebf58b0a913d3ef
dashboard link: https://syzkaller.appspot.com/bug?extid=5420bc7f334912e0c8b2
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+5420bc...@syzkaller.appspotmail.com

R13: 00000000000000a8 R14: 00000000004c1ee6 R15: 0000000000000001
ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 2
======================================================
WARNING: possible circular locking dependency detected
4.19.102-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor.3/6270 is trying to acquire lock:
00000000b02aa2a6 (console_owner){-.-.}, at: console_trylock_spinning kernel/printk/printk.c:1669 [inline]
00000000b02aa2a6 (console_owner){-.-.}, at: vprintk_emit+0x3d5/0x6d0 kernel/printk/printk.c:1936

but task is already holding lock:
00000000770a5ec8 (&(&port->lock)->rlock){-.-.}, at: tty_port_close_start.part.0+0x2b/0x570 drivers/tty/tty_port.c:573

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&(&port->lock)->rlock){-.-.}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x95/0xcd kernel/locking/spinlock.c:152
tty_port_tty_get+0x22/0x90 drivers/tty/tty_port.c:288
tty_port_default_wakeup+0x16/0x40 drivers/tty/tty_port.c:47
tty_port_tty_wakeup+0x57/0x70 drivers/tty/tty_port.c:390
uart_write_wakeup+0x46/0x70 drivers/tty/serial/serial_core.c:103
serial8250_tx_chars+0x495/0xaf0 drivers/tty/serial/8250/8250_port.c:1806
serial8250_handle_irq.part.0+0x261/0x2b0 drivers/tty/serial/8250/8250_port.c:1879
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1865 [inline]
serial8250_default_handle_irq+0xc0/0x150 drivers/tty/serial/8250/8250_port.c:1895
serial8250_interrupt+0xfc/0x1e0 drivers/tty/serial/8250/8250_core.c:125
__handle_irq_event_percpu+0x144/0x8f0 kernel/irq/handle.c:149
handle_irq_event_percpu+0x74/0x160 kernel/irq/handle.c:189
handle_irq_event+0xa7/0x134 kernel/irq/handle.c:206
handle_edge_irq+0x25e/0x8d0 kernel/irq/chip.c:797
generic_handle_irq_desc include/linux/irqdesc.h:155 [inline]
handle_irq+0x39/0x50 arch/x86/kernel/irq_64.c:87
do_IRQ+0x99/0x1d0 arch/x86/kernel/irq.c:246
ret_from_intr+0x0/0x1e
native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:60
arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:556
default_idle_call+0x36/0x90 kernel/sched/idle.c:93
cpuidle_idle_call kernel/sched/idle.c:153 [inline]
do_idle+0x30c/0x4d0 kernel/sched/idle.c:263
cpu_startup_entry+0xc8/0xe0 kernel/sched/idle.c:369
start_secondary+0x3e8/0x5b0 arch/x86/kernel/smpboot.c:271
secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:243

-> #1 (&port_lock_key){-.-.}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x95/0xcd kernel/locking/spinlock.c:152
serial8250_console_write+0x7ca/0x9f0 drivers/tty/serial/8250/8250_port.c:3247
univ8250_console_write+0x5f/0x70 drivers/tty/serial/8250/8250_core.c:590
call_console_drivers kernel/printk/printk.c:1736 [inline]
console_unlock+0xbdf/0x10d0 kernel/printk/printk.c:2429
vprintk_emit+0x280/0x6d0 kernel/printk/printk.c:1937
vprintk_default+0x28/0x30 kernel/printk/printk.c:1979
vprintk_func+0x7e/0x189 kernel/printk/printk_safe.c:398
printk+0xba/0xed kernel/printk/printk.c:2012
register_console+0x77f/0xb90 kernel/printk/printk.c:2745
univ8250_console_init+0x3e/0x4b drivers/tty/serial/8250/8250_core.c:685
console_init+0x4f7/0x761 kernel/printk/printk.c:2831
start_kernel+0x59c/0x825 init/main.c:660
x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:490
x86_64_start_kernel+0x77/0x7b arch/x86/kernel/head64.c:471
secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:243

-> #0 (console_owner){-.-.}:
lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:3903
console_trylock_spinning kernel/printk/printk.c:1690 [inline]
vprintk_emit+0x412/0x6d0 kernel/printk/printk.c:1936
vprintk_default+0x28/0x30 kernel/printk/printk.c:1979
vprintk_func+0x7e/0x189 kernel/printk/printk_safe.c:398
printk+0xba/0xed kernel/printk/printk.c:2012
tty_port_close_start.part.0+0x51a/0x570 drivers/tty/tty_port.c:575
tty_port_close_start drivers/tty/tty_port.c:647 [inline]
tty_port_close+0x4e/0xf0 drivers/tty/tty_port.c:640
tpk_close+0x8e/0xa4 drivers/char/ttyprintk.c:111
tty_release+0x3ba/0xe90 drivers/tty/tty_io.c:1678
__fput+0x2dd/0x8b0 fs/file_table.c:278
____fput+0x16/0x20 fs/file_table.c:309
task_work_run+0x145/0x1c0 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:193 [inline]
exit_to_usermode_loop+0x273/0x2c0 arch/x86/entry/common.c:167
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x53d/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe

other info that might help us debug this:

Chain exists of:
console_owner --> &port_lock_key --> &(&port->lock)->rlock

Possible unsafe locking scenario:

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

*** DEADLOCK ***

2 locks held by syz-executor.3/6270:
#0: 00000000958b4928 (&tty->legacy_mutex){+.+.}, at: tty_lock+0x73/0xb0 drivers/tty/tty_mutex.c:19
#1: 00000000770a5ec8 (&(&port->lock)->rlock){-.-.}, at: tty_port_close_start.part.0+0x2b/0x570 drivers/tty/tty_port.c:573

stack backtrace:
CPU: 0 PID: 6270 Comm: syz-executor.3 Not tainted 4.19.102-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x197/0x210 lib/dump_stack.c:118
print_circular_bug.isra.0.cold+0x1cc/0x28f kernel/locking/lockdep.c:1221
check_prev_add kernel/locking/lockdep.c:1861 [inline]
check_prevs_add kernel/locking/lockdep.c:1974 [inline]
validate_chain kernel/locking/lockdep.c:2415 [inline]
__lock_acquire+0x2e19/0x49c0 kernel/locking/lockdep.c:3411
lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:3903
console_trylock_spinning kernel/printk/printk.c:1690 [inline]
vprintk_emit+0x412/0x6d0 kernel/printk/printk.c:1936
vprintk_default+0x28/0x30 kernel/printk/printk.c:1979
vprintk_func+0x7e/0x189 kernel/printk/printk_safe.c:398
printk+0xba/0xed kernel/printk/printk.c:2012
tty_port_close_start.part.0+0x51a/0x570 drivers/tty/tty_port.c:575
tty_port_close_start drivers/tty/tty_port.c:647 [inline]
tty_port_close+0x4e/0xf0 drivers/tty/tty_port.c:640
tpk_close+0x8e/0xa4 drivers/char/ttyprintk.c:111
tty_release+0x3ba/0xe90 drivers/tty/tty_io.c:1678
__fput+0x2dd/0x8b0 fs/file_table.c:278
____fput+0x16/0x20 fs/file_table.c:309
task_work_run+0x145/0x1c0 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:193 [inline]
exit_to_usermode_loop+0x273/0x2c0 arch/x86/entry/common.c:167
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x53d/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x414f31
Code: 75 14 b8 03 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 04 1b 00 00 c3 48 83 ec 08 e8 0a fc ff ff 48 89 04 24 b8 03 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 53 fc ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:00007fffdf46ddc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 0000000000414f31
RDX: 00000000000f4240 RSI: 0000000000000081 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000760148 R09: ffffffffffffffff
R10: 00007fffdf46de90 R11: 0000000000000293 R12: 000000000075bf20
R13: 0000000000000003 R14: 0000000000760150 R15: 000000000075bf2c
netlink: 4 bytes leftover after parsing attributes in process `syz-executor.0'.
ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 2
ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 2
[U] ^C
[U]
nla_parse: 2 callbacks suppressed
netlink: 256 bytes leftover after parsing attributes in process `syz-executor.4'.
[U] ^C
[U] ^C
[U]
[U]
[U] ^
[U] ^Z
[U] ^\
[U] ^
[U] ^
[U] ^Z
IPVS: set_ctl: invalid protocol: 137 127.0.0.1:20004
[U] ^\
[U] ^Z
[U] ^\
audit: type=1804 audit(1580946621.025:212): pid=10265 uid=0 auid=4294967295 ses=4294967295 subj=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 op=invalid_pcr cause=open_writers comm="syz-executor.4" name="/root/syzkaller-testdir690658694/syzkaller.HRJwz9/4120/bus" dev="sda1" ino=16557 res=1
audit: type=1800 audit(1580946621.035:213): pid=10265 uid=0 auid=4294967295 ses=4294967295 subj=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 op=collect_data cause=failed(directio) comm="syz-executor.4" name="bus" dev="sda1" ino=16557 res=0
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
netlink: 4 bytes leftover after parsing attributes in process `syz-executor.0'.
[U] ^R
[U] ^R
[U] ^R
netlink: 4 bytes leftover after parsing attributes in process `syz-executor.0'.
[U] ^R
netlink: 4 bytes leftover after parsing attributes in process `syz-executor.0'.
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R
Enabling of bearer <eth
team_slave_0> rejected, illegal name
[U] ^R
[U] ^R
[U] ^R
Unknown ioctl 21544
[U] ^R
[U] ^R
[U] ^R
[U] ^R
[U] ^R


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

syzbot

unread,
Feb 15, 2020, 2:33:14 PM2/15/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 98db2bf2 Linux 4.14.171
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=1429d979e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=9dc3f6f9d0ff3b98
dashboard link: https://syzkaller.appspot.com/bug?extid=a4ce323dabefd0c46ba0
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+a4ce32...@syzkaller.appspotmail.com

Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 2
======================================================
WARNING: possible circular locking dependency detected
4.14.171-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor.1/4065 is trying to acquire lock:
(console_owner){-.-.}, at: [<ffffffff814b3661>] console_trylock_spinning kernel/printk/printk.c:1658 [inline]
(console_owner){-.-.}, at: [<ffffffff814b3661>] vprintk_emit kernel/printk/printk.c:1922 [inline]
(console_owner){-.-.}, at: [<ffffffff814b3661>] vprintk_emit+0x2f1/0x600 kernel/printk/printk.c:1888

but task is already holding lock:
(&(&port->lock)->rlock){-.-.}, at: [<ffffffff834d46bb>] tty_port_close_start.part.0+0x2b/0x4e0 drivers/tty/tty_port.c:572

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&(&port->lock)->rlock){-.-.}:
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x95/0xcd kernel/locking/spinlock.c:160
tty_port_tty_get+0x22/0x90 drivers/tty/tty_port.c:287
tty_port_default_wakeup+0x16/0x40 drivers/tty/tty_port.c:46
tty_port_tty_wakeup+0x57/0x70 drivers/tty/tty_port.c:389
uart_write_wakeup+0x46/0x70 drivers/tty/serial/serial_core.c:116
serial8250_tx_chars+0x40d/0xa10 drivers/tty/serial/8250/8250_port.c:1810
serial8250_handle_irq.part.0+0x206/0x250 drivers/tty/serial/8250/8250_port.c:1883
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1869 [inline]
serial8250_default_handle_irq+0xa1/0x120 drivers/tty/serial/8250/8250_port.c:1899
serial8250_interrupt+0xe9/0x1a0 drivers/tty/serial/8250/8250_core.c:129
__handle_irq_event_percpu+0x125/0x7f0 kernel/irq/handle.c:147
handle_irq_event_percpu+0x65/0x130 kernel/irq/handle.c:187
handle_irq_event+0xa7/0x134 kernel/irq/handle.c:204
handle_edge_irq+0x22b/0x840 kernel/irq/chip.c:770
generic_handle_irq_desc include/linux/irqdesc.h:159 [inline]
handle_irq+0x39/0x50 arch/x86/kernel/irq_64.c:87
do_IRQ+0x99/0x1d0 arch/x86/kernel/irq.c:230
ret_from_intr+0x0/0x1e
native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:60
arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:557
default_idle_call+0x36/0x90 kernel/sched/idle.c:98
cpuidle_idle_call kernel/sched/idle.c:156 [inline]
do_idle+0x262/0x3d0 kernel/sched/idle.c:246
cpu_startup_entry+0x1b/0x20 kernel/sched/idle.c:351
rest_init+0x1d9/0x1e2 init/main.c:434
start_kernel+0x65f/0x67d init/main.c:708
x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:399
x86_64_start_kernel+0x77/0x7b arch/x86/kernel/head64.c:380
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240

-> #1 (&port_lock_key){-.-.}:
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x95/0xcd kernel/locking/spinlock.c:160
serial8250_console_write+0x709/0x930 drivers/tty/serial/8250/8250_port.c:3232
univ8250_console_write+0x5f/0x70 drivers/tty/serial/8250/8250_core.c:597
call_console_drivers kernel/printk/printk.c:1725 [inline]
console_unlock+0x9ba/0xed0 kernel/printk/printk.c:2397
vprintk_emit kernel/printk/printk.c:1923 [inline]
vprintk_emit+0x1f9/0x600 kernel/printk/printk.c:1888
vprintk_default+0x28/0x30 kernel/printk/printk.c:1963
vprintk_func+0x5d/0x159 kernel/printk/printk_safe.c:401
printk+0x9e/0xbc kernel/printk/printk.c:1996
register_console+0x614/0x9e0 kernel/printk/printk.c:2716
univ8250_console_init+0x33/0x3f drivers/tty/serial/8250/8250_core.c:692
console_init+0x4d/0x5d kernel/printk/printk.c:2797
start_kernel+0x43c/0x67d init/main.c:634
x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:399
x86_64_start_kernel+0x77/0x7b arch/x86/kernel/head64.c:380
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240

-> #0 (console_owner){-.-.}:
check_prev_add kernel/locking/lockdep.c:1901 [inline]
check_prevs_add kernel/locking/lockdep.c:2018 [inline]
validate_chain kernel/locking/lockdep.c:2460 [inline]
__lock_acquire+0x2cb3/0x4620 kernel/locking/lockdep.c:3487
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
console_trylock_spinning kernel/printk/printk.c:1679 [inline]
vprintk_emit kernel/printk/printk.c:1922 [inline]
vprintk_emit+0x32e/0x600 kernel/printk/printk.c:1888
vprintk_default+0x28/0x30 kernel/printk/printk.c:1963
vprintk_func+0x5d/0x159 kernel/printk/printk_safe.c:401
printk+0x9e/0xbc kernel/printk/printk.c:1996
tty_port_close_start.part.0+0x491/0x4e0 drivers/tty/tty_port.c:574
tty_port_close_start drivers/tty/tty_port.c:646 [inline]
tty_port_close+0x41/0xc0 drivers/tty/tty_port.c:639
tpk_close+0x81/0x97 drivers/char/ttyprintk.c:111
tty_release+0x373/0xd60 drivers/tty/tty_io.c:1670
__fput+0x275/0x7a0 fs/file_table.c:210
____fput+0x16/0x20 fs/file_table.c:244
task_work_run+0x114/0x190 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:191 [inline]
exit_to_usermode_loop+0x1da/0x220 arch/x86/entry/common.c:164
prepare_exit_to_usermode arch/x86/entry/common.c:199 [inline]
syscall_return_slowpath arch/x86/entry/common.c:270 [inline]
do_syscall_64+0x4bc/0x640 arch/x86/entry/common.c:297
entry_SYSCALL_64_after_hwframe+0x42/0xb7

other info that might help us debug this:

Chain exists of:
console_owner --> &port_lock_key --> &(&port->lock)->rlock

Possible unsafe locking scenario:

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

*** DEADLOCK ***

2 locks held by syz-executor.1/4065:
#0: (&tty->legacy_mutex){+.+.}, at: [<ffffffff834d59c8>] tty_lock+0x68/0x80 drivers/tty/tty_mutex.c:19
#1: (&(&port->lock)->rlock){-.-.}, at: [<ffffffff834d46bb>] tty_port_close_start.part.0+0x2b/0x4e0 drivers/tty/tty_port.c:572

stack backtrace:
CPU: 0 PID: 4065 Comm: syz-executor.1 Not tainted 4.14.171-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x142/0x197 lib/dump_stack.c:58
print_circular_bug.isra.0.cold+0x1cc/0x28f kernel/locking/lockdep.c:1258
check_prev_add kernel/locking/lockdep.c:1901 [inline]
check_prevs_add kernel/locking/lockdep.c:2018 [inline]
validate_chain kernel/locking/lockdep.c:2460 [inline]
__lock_acquire+0x2cb3/0x4620 kernel/locking/lockdep.c:3487
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
console_trylock_spinning kernel/printk/printk.c:1679 [inline]
vprintk_emit kernel/printk/printk.c:1922 [inline]
vprintk_emit+0x32e/0x600 kernel/printk/printk.c:1888
vprintk_default+0x28/0x30 kernel/printk/printk.c:1963
vprintk_func+0x5d/0x159 kernel/printk/printk_safe.c:401
printk+0x9e/0xbc kernel/printk/printk.c:1996
tty_port_close_start.part.0+0x491/0x4e0 drivers/tty/tty_port.c:574
tty_port_close_start drivers/tty/tty_port.c:646 [inline]
tty_port_close+0x41/0xc0 drivers/tty/tty_port.c:639
tpk_close+0x81/0x97 drivers/char/ttyprintk.c:111
tty_release+0x373/0xd60 drivers/tty/tty_io.c:1670
__fput+0x275/0x7a0 fs/file_table.c:210
____fput+0x16/0x20 fs/file_table.c:244
task_work_run+0x114/0x190 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:191 [inline]
exit_to_usermode_loop+0x1da/0x220 arch/x86/entry/common.c:164
prepare_exit_to_usermode arch/x86/entry/common.c:199 [inline]
syscall_return_slowpath arch/x86/entry/common.c:270 [inline]
do_syscall_64+0x4bc/0x640 arch/x86/entry/common.c:297
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x416261
RSP: 002b:00007ffdd45e7f10 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000009 RCX: 0000000000416261
RDX: 0000000000000000 RSI: 0000000000000081 RDI: 0000000000000008
RBP: 0000000000000000 R08: 0000000000770d70 R09: ffffffffffffffff
R10: 00007ffdd45e7fe0 R11: 0000000000000293 R12: 000000000076bf20
R13: 0000000000000005 R14: 0000000000770d78 R15: 000000000076bf2c
ptrace attach of "/root/syz-executor.3"[4085] was attempted by "/root/syz-executor.3"[4086]
Cannot find set identified by id 0 to match
ptrace attach of "/root/syz-executor.0"[4102] was attempted by "/root/syz-executor.0"[4103]
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match
Cannot find set identified by id 0 to match

syzbot

unread,
Oct 30, 2020, 8:22:19 AM10/30/20
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following issue on:

HEAD commit: 2b791501 Linux 4.14.203
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=151b06d4500000
kernel config: https://syzkaller.appspot.com/x/.config?x=e52bb6f2a595a463
dashboard link: https://syzkaller.appspot.com/bug?extid=a4ce323dabefd0c46ba0
compiler: gcc (GCC) 10.1.0-syz 20200507
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=11b291f4500000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=13e80a5c500000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+a4ce32...@syzkaller.appspotmail.com

wlan0: Creating new IBSS network, BSSID 50:50:50:50:50:50
wlan0: Creating new IBSS network, BSSID 50:50:50:50:50:50
ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 21
ieee80211 phy10: hwaddr 02:00:00:00:0a:00 registered
======================================================
WARNING: possible circular locking dependency detected
4.14.203-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor330/9523 is trying to acquire lock:
(console_owner){....}, at: [<ffffffff8145a90a>] console_trylock_spinning kernel/printk/printk.c:1658 [inline]
(console_owner){....}, at: [<ffffffff8145a90a>] vprintk_emit+0x32a/0x620 kernel/printk/printk.c:1922

but task is already holding lock:
(&(&port->lock)->rlock){-.-.}, at: [<ffffffff835e7238>] tty_port_close_start.part.0+0x28/0x4c0 drivers/tty/tty_port.c:573

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&(&port->lock)->rlock){-.-.}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x8c/0xc0 kernel/locking/spinlock.c:160
tty_port_tty_get+0x1d/0x80 drivers/tty/tty_port.c:288
tty_port_default_wakeup+0x11/0x40 drivers/tty/tty_port.c:46
serial8250_tx_chars+0x3fe/0xbf0 drivers/tty/serial/8250/8250_port.c:1810
serial8250_handle_irq.part.0+0x28d/0x330 drivers/tty/serial/8250/8250_port.c:1897
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1870 [inline]
serial8250_default_handle_irq+0x8a/0x1f0 drivers/tty/serial/8250/8250_port.c:1913
serial8250_interrupt+0xf3/0x210 drivers/tty/serial/8250/8250_core.c:129
__handle_irq_event_percpu+0xee/0x7f0 kernel/irq/handle.c:147
handle_irq_event_percpu kernel/irq/handle.c:187 [inline]
handle_irq_event+0xf0/0x246 kernel/irq/handle.c:204
handle_edge_irq+0x224/0xc40 kernel/irq/chip.c:770
generic_handle_irq_desc include/linux/irqdesc.h:159 [inline]
handle_irq+0x35/0x50 arch/x86/kernel/irq_64.c:87
do_IRQ+0x93/0x1d0 arch/x86/kernel/irq.c:230
ret_from_intr+0x0/0x1e
native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:60
arch_safe_halt arch/x86/include/asm/paravirt.h:94 [inline]
default_idle+0x47/0x370 arch/x86/kernel/process.c:558
cpuidle_idle_call kernel/sched/idle.c:156 [inline]
do_idle+0x250/0x3c0 kernel/sched/idle.c:246
cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:351
start_secondary+0x4db/0x670 arch/x86/kernel/smpboot.c:272
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240

-> #1 (&port_lock_key){-.-.}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x8c/0xc0 kernel/locking/spinlock.c:160
serial8250_console_write+0x7a7/0x9d0 drivers/tty/serial/8250/8250_port.c:3253
call_console_drivers kernel/printk/printk.c:1725 [inline]
console_unlock+0x99d/0xf20 kernel/printk/printk.c:2400
vprintk_emit+0x224/0x620 kernel/printk/printk.c:1923
vprintk_func+0x58/0x152 kernel/printk/printk_safe.c:401
printk+0x9e/0xbc kernel/printk/printk.c:1996
register_console+0x6f4/0xad0 kernel/printk/printk.c:2719
univ8250_console_init+0x2f/0x3a drivers/tty/serial/8250/8250_core.c:691
console_init+0x46/0x53 kernel/printk/printk.c:2800
start_kernel+0x52e/0x770 init/main.c:634
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240

-> #0 (console_owner){....}:
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
console_trylock_spinning kernel/printk/printk.c:1679 [inline]
vprintk_emit+0x367/0x620 kernel/printk/printk.c:1922
vprintk_func+0x58/0x152 kernel/printk/printk_safe.c:401
printk+0x9e/0xbc kernel/printk/printk.c:1996
tty_port_close_start.part.0+0x46c/0x4c0 drivers/tty/tty_port.c:575
tty_port_close_start drivers/tty/tty_port.c:647 [inline]
tty_port_close+0x3b/0x130 drivers/tty/tty_port.c:640
tty_release+0x40b/0x10d0 drivers/tty/tty_io.c:1670
__fput+0x25f/0x7a0 fs/file_table.c:210
task_work_run+0x11f/0x190 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:191 [inline]
exit_to_usermode_loop+0x1ad/0x200 arch/x86/entry/common.c:164
prepare_exit_to_usermode arch/x86/entry/common.c:199 [inline]
syscall_return_slowpath arch/x86/entry/common.c:270 [inline]
do_syscall_64+0x4a3/0x640 arch/x86/entry/common.c:297
entry_SYSCALL_64_after_hwframe+0x46/0xbb

other info that might help us debug this:

Chain exists of:
console_owner --> &port_lock_key --> &(&port->lock)->rlock

Possible unsafe locking scenario:

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

*** DEADLOCK ***

2 locks held by syz-executor330/9523:
#0: (&tty->legacy_mutex){+.+.}, at: [<ffffffff835e89af>] tty_lock+0x5f/0x70 drivers/tty/tty_mutex.c:19
#1: (&(&port->lock)->rlock){-.-.}, at: [<ffffffff835e7238>] tty_port_close_start.part.0+0x28/0x4c0 drivers/tty/tty_port.c:573

stack backtrace:
CPU: 1 PID: 9523 Comm: syz-executor330 Not tainted 4.14.203-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x1b2/0x283 lib/dump_stack.c:58
print_circular_bug.constprop.0.cold+0x2d7/0x41e kernel/locking/lockdep.c:1258
check_prev_add kernel/locking/lockdep.c:1905 [inline]
check_prevs_add kernel/locking/lockdep.c:2022 [inline]
validate_chain kernel/locking/lockdep.c:2464 [inline]
__lock_acquire+0x2e0e/0x3f20 kernel/locking/lockdep.c:3491
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
console_trylock_spinning kernel/printk/printk.c:1679 [inline]
vprintk_emit+0x367/0x620 kernel/printk/printk.c:1922
vprintk_func+0x58/0x152 kernel/printk/printk_safe.c:401
printk+0x9e/0xbc kernel/printk/printk.c:1996
tty_port_close_start.part.0+0x46c/0x4c0 drivers/tty/tty_port.c:575
tty_port_close_start drivers/tty/tty_port.c:647 [inline]
tty_port_close+0x3b/0x130 drivers/tty/tty_port.c:640
tty_release+0x40b/0x10d0 drivers/tty/tty_io.c:1670
__fput+0x25f/0x7a0 fs/file_table.c:210
task_work_run+0x11f/0x190 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:191 [inline]
exit_to_usermode_loop+0x1ad/0x200 arch/x86/entry/common.c:164
prepare_exit_to_usermode arch/x86/entry/common.c:199 [inline]
syscall_return_slowpath arch/x86/entry/common.c:270 [inline]
do_syscall_64+0x4a3/0x640 arch/x86/entry/common.c:297
entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x409621
RSP: 002b:00007fff253b9f90 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 0000000000409621
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000003
RBP: 00000000006e1c30 R08: 00000000004b36ec R09: 00000000004b36ec
R10: 00007fff253b9fb0 R11: 0000000000000293 R12: 00000000006e1c3c
R13: 0000000000000001 R14: 000000000000002d R15: 20c49ba5e353f7cf
ieee80211 phy9: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy8: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy9: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy8: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy9: mac80211_hwsim_bss_info_changed(changed=0x40000 vif->addr=02:00:00:00:09:00)
ieee80211 phy8: mac80211_hwsim_bss_info_changed(changed=0x40000 vif->addr=02:00:00:00:08:00)
ieee80211 phy9: TX Power: 20 dBm
ieee80211 phy8: TX Power: 20 dBm
ieee80211 phy9: mac80211_hwsim_bss_info_changed(changed=0x4000 vif->addr=02:00:00:00:09:00)
ieee80211 phy8: mac80211_hwsim_bss_info_changed(changed=0x4000 vif->addr=02:00:00:00:08:00)
ieee80211 phy9: mac80211_hwsim_conf_tx (queue=0 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy8: mac80211_hwsim_conf_tx (queue=0 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy9: mac80211_hwsim_conf_tx (queue=1 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy8: mac80211_hwsim_conf_tx (queue=1 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy9: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy8: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy9: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy8: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy9: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:09:00)
ieee80211 phy8: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:08:00)
ieee80211 phy9: mac80211_hwsim_bss_info_changed(changed=0x8bfe vif->addr=02:00:00:00:09:00)
ieee80211 phy8: mac80211_hwsim_bss_info_changed(changed=0x8bfe vif->addr=02:00:00:00:08:00)
ieee80211 phy9: mac80211_hwsim_bss_info_changed: BSSID changed: 50:50:50:50:50:50
ieee80211 phy11: Selected rate control algorithm 'minstrel_ht'
ieee80211 phy9: BCN EN: 1 (BI=100)
ieee80211 phy8: mac80211_hwsim_bss_info_changed: BSSID changed: 50:50:50:50:50:50
ieee80211 phy9: ERP_CTS_PROT: 0
ieee80211 phy11: hwaddr 02:00:00:00:0b:00 registered
ieee80211 phy9: ERP_PREAMBLE: 0
ieee80211 phy8: BCN EN: 1 (BI=100)
ieee80211 phy9: ERP_SLOT: 0
ieee80211 phy8: ERP_CTS_PROT: 0
ieee80211 phy9: HT: op_mode=0xb
ieee80211 phy12: Selected rate control algorithm 'minstrel_ht'
ieee80211 phy9: BASIC_RATES: 0x1
ieee80211 phy8: ERP_PREAMBLE: 0
ieee80211 phy8: ERP_SLOT: 0
ieee80211 phy8: HT: op_mode=0xb
ieee80211 phy8: BASIC_RATES: 0x1
IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
ieee80211 phy12: hwaddr 02:00:00:00:0c:00 registered
IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
ieee80211 phy10: mac80211_hwsim_start
ieee80211 phy10: mac80211_hwsim_add_interface (type=1 mac_addr=02:00:00:00:0a:00)
ieee80211 phy10: mac80211_hwsim_bss_info_changed(changed=0xe vif->addr=02:00:00:00:0a:00)
ieee80211 phy10: ERP_CTS_PROT: 0
ieee80211 phy10: ERP_PREAMBLE: 0
ieee80211 phy10: ERP_SLOT: 0
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=0 txop=47 cw_min=3 cw_max=7 aifs=2)
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=1 txop=94 cw_min=7 cw_max=15 aifs=2)
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=3)
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=7)
ieee80211 phy10: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0a:00)
ieee80211 phy10: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=1 ps=0 smps=static)
ieee80211 phy10: mac80211_hwsim_configure_filter
IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
ieee80211 phy10: mac80211_hwsim_configure_filter
ieee80211 phy8: mac80211_hwsim_configure_filter
ieee80211 phy9: mac80211_hwsim_configure_filter
ieee80211 phy11: mac80211_hwsim_start
ieee80211 phy11: mac80211_hwsim_add_interface (type=1 mac_addr=02:00:00:00:0b:00)
ieee80211 phy11: mac80211_hwsim_bss_info_changed(changed=0xe vif->addr=02:00:00:00:0b:00)
ieee80211 phy11: ERP_CTS_PROT: 0
ieee80211 phy11: ERP_PREAMBLE: 0
ieee80211 phy11: ERP_SLOT: 0
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=0 txop=47 cw_min=3 cw_max=7 aifs=2)
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=1 txop=94 cw_min=7 cw_max=15 aifs=2)
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=3)
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=7)
ieee80211 phy11: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0b:00)
ieee80211 phy11: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=1 ps=0 smps=static)
ieee80211 phy11: mac80211_hwsim_configure_filter
IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
ieee80211 phy11: mac80211_hwsim_configure_filter
ieee80211 phy10: mac80211_hwsim_bss_info_changed(changed=0x10 vif->addr=02:00:00:00:0a:00)
ieee80211 phy10: HT: op_mode=0xb
wlan1: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
wlan1: Creating new IBSS network, BSSID 50:50:50:50:50:50
ieee80211 phy12: mac80211_hwsim_start
ieee80211 phy12: mac80211_hwsim_add_interface (type=1 mac_addr=02:00:00:00:0c:00)
ieee80211 phy10: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy12: mac80211_hwsim_bss_info_changed(changed=0xe vif->addr=02:00:00:00:0c:00)
ieee80211 phy10: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy12: ERP_CTS_PROT: 0
ieee80211 phy10: mac80211_hwsim_bss_info_changed(changed=0x40000 vif->addr=02:00:00:00:0a:00)
ieee80211 phy12: ERP_PREAMBLE: 0
ieee80211 phy10: TX Power: 20 dBm
ieee80211 phy12: ERP_SLOT: 0
ieee80211 phy10: mac80211_hwsim_bss_info_changed(changed=0x4000 vif->addr=02:00:00:00:0a:00)
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=0 txop=47 cw_min=3 cw_max=7 aifs=2)
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=0 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=1 txop=94 cw_min=7 cw_max=15 aifs=2)
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=1 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=3)
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=7)
ieee80211 phy10: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy12: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0c:00)
ieee80211 phy10: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0a:00)
ieee80211 phy12: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=1 ps=0 smps=static)
ieee80211 phy10: mac80211_hwsim_bss_info_changed(changed=0x8bfe vif->addr=02:00:00:00:0a:00)
ieee80211 phy12: mac80211_hwsim_configure_filter
ieee80211 phy10: mac80211_hwsim_bss_info_changed: BSSID changed: 50:50:50:50:50:50
ieee80211 phy10: BCN EN: 1 (BI=100)
ieee80211 phy10: ERP_CTS_PROT: 0
ieee80211 phy10: ERP_PREAMBLE: 0
ieee80211 phy10: ERP_SLOT: 0
ieee80211 phy10: HT: op_mode=0xb
ieee80211 phy10: BASIC_RATES: 0x1
IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
ieee80211 phy12: mac80211_hwsim_configure_filter
ieee80211 phy11: mac80211_hwsim_bss_info_changed(changed=0x10 vif->addr=02:00:00:00:0b:00)
ieee80211 phy11: HT: op_mode=0xb
wlan1: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
wlan1: Creating new IBSS network, BSSID 50:50:50:50:50:50
ieee80211 phy10: mac80211_hwsim_configure_filter
ieee80211 phy11: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy12: mac80211_hwsim_bss_info_changed(changed=0x10 vif->addr=02:00:00:00:0c:00)
ieee80211 phy11: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy12: HT: op_mode=0xb
ieee80211 phy11: mac80211_hwsim_bss_info_changed(changed=0x40000 vif->addr=02:00:00:00:0b:00)
wlan0: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
ieee80211 phy11: TX Power: 20 dBm
ieee80211 phy11: mac80211_hwsim_bss_info_changed(changed=0x4000 vif->addr=02:00:00:00:0b:00)
ieee80211 phy13: Selected rate control algorithm 'minstrel_ht'
wlan0: Creating new IBSS network, BSSID 50:50:50:50:50:50
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=0 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy12: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=1 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: hwaddr 02:00:00:00:0d:00 registered
ieee80211 phy12: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: mac80211_hwsim_start
ieee80211 phy12: mac80211_hwsim_bss_info_changed(changed=0x40000 vif->addr=02:00:00:00:0c:00)
ieee80211 phy11: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: mac80211_hwsim_add_interface (type=1 mac_addr=02:00:00:00:0d:00)
ieee80211 phy11: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0b:00)
ieee80211 phy12: TX Power: 20 dBm
ieee80211 phy12: mac80211_hwsim_bss_info_changed(changed=0x4000 vif->addr=02:00:00:00:0c:00)
ieee80211 phy11: mac80211_hwsim_bss_info_changed(changed=0x8bfe vif->addr=02:00:00:00:0b:00)
ieee80211 phy13: mac80211_hwsim_bss_info_changed(changed=0xe vif->addr=02:00:00:00:0d:00)
ieee80211 phy11: mac80211_hwsim_bss_info_changed: BSSID changed: 50:50:50:50:50:50
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=0 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy11: BCN EN: 1 (BI=100)
ieee80211 phy13: ERP_CTS_PROT: 0
ieee80211 phy11: ERP_CTS_PROT: 0
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=1 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy11: ERP_PREAMBLE: 0
ieee80211 phy13: ERP_PREAMBLE: 0
ieee80211 phy13: ERP_SLOT: 0
ieee80211 phy11: ERP_SLOT: 0
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=0 txop=47 cw_min=3 cw_max=7 aifs=2)
ieee80211 phy11: HT: op_mode=0xb
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy11: BASIC_RATES: 0x1
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=1 txop=94 cw_min=7 cw_max=15 aifs=2)
ieee80211 phy12: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=3)
ieee80211 phy12: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0c:00)
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=7)
ieee80211 phy12: mac80211_hwsim_bss_info_changed(changed=0x8bfe vif->addr=02:00:00:00:0c:00)
ieee80211 phy13: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0d:00)
ieee80211 phy12: mac80211_hwsim_bss_info_changed: BSSID changed: 50:50:50:50:50:50
ieee80211 phy13: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=1 ps=0 smps=static)
ieee80211 phy12: BCN EN: 1 (BI=100)
IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
ieee80211 phy13: mac80211_hwsim_configure_filter
ieee80211 phy12: ERP_CTS_PROT: 0
ieee80211 phy13: mac80211_hwsim_bss_info_changed(changed=0x10 vif->addr=02:00:00:00:0d:00)
ieee80211 phy12: ERP_PREAMBLE: 0
ieee80211 phy12: ERP_SLOT: 0
ieee80211 phy12: HT: op_mode=0xb
ieee80211 phy13: HT: op_mode=0xb
ieee80211 phy12: BASIC_RATES: 0x1
wlan1: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
wlan1: Creating new IBSS network, BSSID 50:50:50:50:50:50
IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
ieee80211 phy13: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy12: mac80211_hwsim_configure_filter
ieee80211 phy13: mac80211_hwsim_config (freq=2412(2412 - 0)/noht idle=0 ps=0 smps=static)
ieee80211 phy11: mac80211_hwsim_configure_filter
ieee80211 phy13: mac80211_hwsim_bss_info_changed(changed=0x40000 vif->addr=02:00:00:00:0d:00)
ieee80211 phy13: TX Power: 20 dBm
ieee80211 phy13: mac80211_hwsim_bss_info_changed(changed=0x4000 vif->addr=02:00:00:00:0d:00)
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=0 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=1 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=2 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: mac80211_hwsim_conf_tx (queue=3 txop=0 cw_min=15 cw_max=1023 aifs=2)
ieee80211 phy13: mac80211_hwsim_bss_info_changed(changed=0x2000 vif->addr=02:00:00:00:0d:00)
ieee80211 phy13: mac80211_hwsim_bss_info_changed(changed=0x8bfe vif->addr=02:00:00:00:0d:00)
ieee80211 phy13: mac80211_hwsim_bss_info_changed: BSSID changed: 50:50:50:50:50:50
ieee80211 phy13: BCN EN: 1 (BI=100)
ieee80211 phy13: ERP_CTS_PROT: 0
ieee80211 phy13: ERP_PREAMBLE: 0
ieee80211 phy13: ERP_SLOT: 0
ieee80211 phy13: HT: op_mode=0xb
ieee80211 phy13: BASIC_RATES: 0x1
IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
ieee80211 phy13: mac80211_hwsim_configure_filter

syzbot

unread,
Nov 14, 2020, 9:23:32 PM11/14/20
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following issue on:

HEAD commit: 31acccdc Linux 4.19.157
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=17d0b906500000
kernel config: https://syzkaller.appspot.com/x/.config?x=1f604e014c43fe09
dashboard link: https://syzkaller.appspot.com/bug?extid=5420bc7f334912e0c8b2
compiler: gcc (GCC) 10.1.0-syz 20200507
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=114d8af6500000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=10d0447a500000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+5420bc...@syzkaller.appspotmail.com

wlan0: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
wlan0: Creating new IBSS network, BSSID 50:50:50:50:50:50
ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 39
======================================================
WARNING: possible circular locking dependency detected
4.19.157-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor686/9659 is trying to acquire lock:
00000000f946559c (console_owner){....}, at: console_trylock_spinning kernel/printk/printk.c:1697 [inline]
00000000f946559c (console_owner){....}, at: vprintk_emit+0x3fe/0x740 kernel/printk/printk.c:1964

but task is already holding lock:
0000000070bdabad (&(&port->lock)->rlock){-.-.}, at: tty_port_close_start.part.0+0x28/0x540 drivers/tty/tty_port.c:574

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&(&port->lock)->rlock){-.-.}:
tty_port_tty_get+0x1d/0x80 drivers/tty/tty_port.c:289
tty_port_default_wakeup+0x11/0x40 drivers/tty/tty_port.c:47
serial8250_tx_chars+0x490/0xaf0 drivers/tty/serial/8250/8250_port.c:1806
serial8250_handle_irq.part.0+0x31f/0x3d0 drivers/tty/serial/8250/8250_port.c:1893
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1866 [inline]
serial8250_default_handle_irq+0xae/0x220 drivers/tty/serial/8250/8250_port.c:1909
serial8250_interrupt+0x101/0x240 drivers/tty/serial/8250/8250_core.c:125
__handle_irq_event_percpu+0x27e/0x8e0 kernel/irq/handle.c:149
handle_irq_event_percpu kernel/irq/handle.c:189 [inline]
handle_irq_event+0x102/0x285 kernel/irq/handle.c:206
handle_edge_irq+0x260/0xcf0 kernel/irq/chip.c:797
generic_handle_irq_desc include/linux/irqdesc.h:155 [inline]
handle_irq+0x35/0x50 arch/x86/kernel/irq_64.c:87
do_IRQ+0x93/0x1c0 arch/x86/kernel/irq.c:246
ret_from_intr+0x0/0x1e
native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:60
arch_safe_halt arch/x86/include/asm/paravirt.h:94 [inline]
default_idle+0x49/0x310 arch/x86/kernel/process.c:557
cpuidle_idle_call kernel/sched/idle.c:153 [inline]
do_idle+0x2ec/0x4b0 kernel/sched/idle.c:263
cpu_startup_entry+0xc5/0xe0 kernel/sched/idle.c:369
start_kernel+0x8d6/0x911 init/main.c:736
secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:243

-> #1 (&port_lock_key){-.-.}:
serial8250_console_write+0x89b/0xad0 drivers/tty/serial/8250/8250_port.c:3270
call_console_drivers kernel/printk/printk.c:1764 [inline]
console_unlock+0xbb6/0x1110 kernel/printk/printk.c:2460
vprintk_emit+0x2d1/0x740 kernel/printk/printk.c:1965
vprintk_func+0x79/0x17e kernel/printk/printk_safe.c:397
printk+0xba/0xed kernel/printk/printk.c:2040
register_console+0x87f/0xc90 kernel/printk/printk.c:2776
univ8250_console_init+0x3a/0x46 drivers/tty/serial/8250/8250_core.c:684
console_init+0x4cb/0x718 kernel/printk/printk.c:2862
start_kernel+0x686/0x911 init/main.c:659
secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:243

-> #0 (console_owner){....}:
console_trylock_spinning kernel/printk/printk.c:1718 [inline]
vprintk_emit+0x43b/0x740 kernel/printk/printk.c:1964
vprintk_func+0x79/0x17e kernel/printk/printk_safe.c:397
printk+0xba/0xed kernel/printk/printk.c:2040
tty_port_close_start.part.0+0x4f3/0x540 drivers/tty/tty_port.c:576
tty_port_close_start drivers/tty/tty_port.c:648 [inline]
tty_port_close+0x46/0x160 drivers/tty/tty_port.c:641
tty_release+0x45e/0x1210 drivers/tty/tty_io.c:1678
__fput+0x2ce/0x890 fs/file_table.c:278
task_work_run+0x148/0x1c0 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:193 [inline]
exit_to_usermode_loop+0x251/0x2a0 arch/x86/entry/common.c:167
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x538/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe

other info that might help us debug this:

Chain exists of:
console_owner --> &port_lock_key --> &(&port->lock)->rlock

Possible unsafe locking scenario:

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

*** DEADLOCK ***

2 locks held by syz-executor686/9659:
#0: 000000008e2197ec (&tty->legacy_mutex){+.+.}, at: tty_lock+0x6a/0xa0 drivers/tty/tty_mutex.c:19
#1: 0000000070bdabad (&(&port->lock)->rlock){-.-.}, at: tty_port_close_start.part.0+0x28/0x540 drivers/tty/tty_port.c:574

stack backtrace:
CPU: 0 PID: 9659 Comm: syz-executor686 Not tainted 4.19.157-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1fc/0x2fe lib/dump_stack.c:118
print_circular_bug.constprop.0.cold+0x2d7/0x41e kernel/locking/lockdep.c:1221
check_prev_add kernel/locking/lockdep.c:1865 [inline]
check_prevs_add kernel/locking/lockdep.c:1978 [inline]
validate_chain kernel/locking/lockdep.c:2419 [inline]
__lock_acquire+0x30c9/0x3ff0 kernel/locking/lockdep.c:3415
lock_acquire+0x170/0x3c0 kernel/locking/lockdep.c:3907
console_trylock_spinning kernel/printk/printk.c:1718 [inline]
vprintk_emit+0x43b/0x740 kernel/printk/printk.c:1964
vprintk_func+0x79/0x17e kernel/printk/printk_safe.c:397
printk+0xba/0xed kernel/printk/printk.c:2040
tty_port_close_start.part.0+0x4f3/0x540 drivers/tty/tty_port.c:576
tty_port_close_start drivers/tty/tty_port.c:648 [inline]
tty_port_close+0x46/0x160 drivers/tty/tty_port.c:641
tty_release+0x45e/0x1210 drivers/tty/tty_io.c:1678
__fput+0x2ce/0x890 fs/file_table.c:278
task_work_run+0x148/0x1c0 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:193 [inline]
exit_to_usermode_loop+0x251/0x2a0 arch/x86/entry/common.c:167
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x538/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x409961
Code: 75 14 b8 03 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 24 1a 00 00 c3 48 83 ec 08 e8 0a fc ff ff 48 89 04 24 b8 03 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 53 fc ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:00007ffc2f25fff0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 0000000000409961
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000003
RBP: 00000000006e1c30 R08: 00000000004b3912 R09: 00000000004b3912
R10: 00007ffc2f260010 R11: 0000000000000293 R12: 00000000006e1c3c
R13: 0000000000000001 R14: 000000000000002d R15: 20c49ba5e353f7cf
IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
wlan0: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
ieee80211 phy13: Selected rate control algorithm 'minstrel_ht'
wlan0: Creating new IBSS network, BSSID 50:50:50:50:50:50
IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
wlan1: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
wlan1: Creating new IBSS network, BSSID 50:50:50:50:50:50
IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
wlan1: Created IBSS using preconfigured BSSID 50:50:50:50:50:50
wlan1: Creating new IBSS network, BSSID 50:50:50:50:50:50

syzbot

unread,
Jun 15, 2021, 10:49:11 AM6/15/21
to syzkaller...@googlegroups.com
syzbot suspects this issue was fixed by commit:

commit 1f51881e2dccac944682e08b23ec441678809443
Author: Tetsuo Handa <penguin...@i-love.sakura.ne.jp>
Date: Thu Apr 15 00:22:22 2021 +0000

ttyprintk: Add TTY hangup callback.

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=106efb4fd00000
start commit: 31acccdc Linux 4.19.157
git tree: linux-4.19.y
If the result looks correct, please mark the issue as fixed by replying with:

#syz fix: ttyprintk: Add TTY hangup callback.

For information about bisection process see: https://goo.gl/tpsmEJ#bisection
Reply all
Reply to author
Forward
0 new messages