syzbot


BUG: sleeping function called from invalid context in tpk_write

Status: fixed on 2020/03/06 21:15
Reported-by: syzbot+2564499426f9e3e7b6df@syzkaller.appspotmail.com
Fix commit: fb56687038cf ttyprintk: fix a potential deadlock in interrupt context issue
First crash: 1596d, last: 1535d
Fix bisection: fixed by (bisect log) :
commit fb56687038cfd0e82b6185bdb134d5d7c2b6073f
Author: Zhenzhong Duan <zhenzhong.duan@gmail.com>
Date: Mon Jan 13 03:48:42 2020 +0000

  ttyprintk: fix a potential deadlock in interrupt context issue

  
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
linux-4.14 BUG: sleeping function called from invalid context in tpk_write C done 10 1535d 1596d 1/1 fixed on 2020/03/06 21:15
upstream BUG: sleeping function called from invalid context in tpk_write kernel C done 12 1553d 1594d 15/26 fixed on 2020/02/18 14:31

Sample crash report:
Bluetooth: hci0: sending frame failed (-49)
Bluetooth: hci0: command 0x1003 tx timeout
Bluetooth: hci0: sending frame failed (-49)
Bluetooth: hci0: command 0x1001 tx timeout
Bluetooth: hci0: sending frame failed (-49)
BUG: sleeping function called from invalid context at kernel/locking/mutex.c:908
in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
1 lock held by swapper/0/0:
 #0: 00000000186cb519 ((&sp->resync_t)){+.-.}, at: lockdep_copy_map include/linux/lockdep.h:168 [inline]
 #0: 00000000186cb519 ((&sp->resync_t)){+.-.}, at: call_timer_fn+0xda/0x720 kernel/time/timer.c:1316
Preemption disabled at:
[<ffffffff874b23fd>] schedule_preempt_disabled+0x1d/0x20 kernel/sched/core.c:3618
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.88-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x197/0x210 lib/dump_stack.c:118
 ___might_sleep.cold+0x1bd/0x1f6 kernel/sched/core.c:6191
 __might_sleep+0x95/0x190 kernel/sched/core.c:6144
 __mutex_lock_common kernel/locking/mutex.c:908 [inline]
 __mutex_lock+0xc8/0x1300 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 tpk_write+0x5d/0x340 drivers/char/ttyprintk.c:123
 resync_tnc+0x1b6/0x320 drivers/net/hamradio/6pack.c:522
 call_timer_fn+0x18d/0x720 kernel/time/timer.c:1326
 expire_timers kernel/time/timer.c:1363 [inline]
 __run_timers kernel/time/timer.c:1684 [inline]
 __run_timers kernel/time/timer.c:1652 [inline]
 run_timer_softirq+0x64f/0x16a0 kernel/time/timer.c:1697
 __do_softirq+0x25c/0x921 kernel/softirq.c:292
 invoke_softirq kernel/softirq.c:372 [inline]
 irq_exit+0x180/0x1d0 kernel/softirq.c:412
 exiting_irq arch/x86/include/asm/apic.h:536 [inline]
 smp_apic_timer_interrupt+0x13b/0x550 arch/x86/kernel/apic/apic.c:1094
 apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:893
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
Code: ff ff 48 89 df e8 42 72 56 fa eb 82 e9 07 00 00 00 0f 00 2d 24 b7 5b 00 f4 c3 66 90 e9 07 00 00 00 0f 00 2d 14 b7 5b 00 fb f4 <c3> 90 55 48 89 e5 41 57 41 56 41 55 41 54 53 e8 ce 57 0d fa e8 b9
RSP: 0018:ffffffff88e07cb0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff11e4b74 RBX: ffffffff88e79ec0 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff88e7a73c
RBP: ffffffff88e07ce0 R08: ffffffff88e79ec0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: ffffffff88f25b90 R14: 0000000000000000 R15: ffffffff88e79ec0
 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
 rest_init+0x219/0x222 init/main.c:441
 start_kernel+0x88c/0x8c5 init/main.c:737
 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

================================
WARNING: inconsistent lock state
4.19.88-syzkaller #0 Tainted: G        W        
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
0000000038bc970f (&tpk_port.port_write_mutex){+.?.}, at: tpk_write+0x5d/0x340 drivers/char/ttyprintk.c:123
{SOFTIRQ-ON-W} state was registered at:
  lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:3903
  __mutex_lock_common kernel/locking/mutex.c:925 [inline]
  __mutex_lock+0xf7/0x1300 kernel/locking/mutex.c:1072
  mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
  tpk_write+0x5d/0x340 drivers/char/ttyprintk.c:123
  tnc_init drivers/net/hamradio/6pack.c:536 [inline]
  sixpack_open+0x9d3/0xbf5 drivers/net/hamradio/6pack.c:632
  tty_ldisc_open.isra.0+0x89/0xd0 drivers/tty/tty_ldisc.c:462
  tty_set_ldisc+0x2e3/0x690 drivers/tty/tty_ldisc.c:587
  tiocsetd drivers/tty/tty_io.c:2359 [inline]
  tty_ioctl+0x65e/0x1510 drivers/tty/tty_io.c:2603
  vfs_ioctl fs/ioctl.c:46 [inline]
  file_ioctl fs/ioctl.c:501 [inline]
  do_vfs_ioctl+0xd5f/0x1380 fs/ioctl.c:688
  ksys_ioctl+0xab/0xd0 fs/ioctl.c:705
  __do_sys_ioctl fs/ioctl.c:712 [inline]
  __se_sys_ioctl fs/ioctl.c:710 [inline]
  __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:710
  do_syscall_64+0xfd/0x620 arch/x86/entry/common.c:293
  entry_SYSCALL_64_after_hwframe+0x49/0xbe
irq event stamp: 202032
hardirqs last  enabled at (202032): [<ffffffff87449fd6>] dump_stack+0x1f6/0x210 lib/dump_stack.c:123
hardirqs last disabled at (202031): [<ffffffff87449e91>] dump_stack+0xb1/0x210 lib/dump_stack.c:100
softirqs last  enabled at (201968): [<ffffffff81401edc>] _local_bh_enable+0x1c/0x30 kernel/softirq.c:162
softirqs last disabled at (201969): [<ffffffff81404a60>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (201969): [<ffffffff81404a60>] irq_exit+0x180/0x1d0 kernel/softirq.c:412

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(&tpk_port.port_write_mutex);
  <Interrupt>
    lock(&tpk_port.port_write_mutex);

 *** DEADLOCK ***

1 lock held by swapper/0/0:
 #0: 00000000186cb519 ((&sp->resync_t)){+.-.}, at: lockdep_copy_map include/linux/lockdep.h:168 [inline]
 #0: 00000000186cb519 ((&sp->resync_t)){+.-.}, at: call_timer_fn+0xda/0x720 kernel/time/timer.c:1316

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W         4.19.88-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x197/0x210 lib/dump_stack.c:118
 print_usage_bug.cold+0x330/0x42a kernel/locking/lockdep.c:2540
 valid_state kernel/locking/lockdep.c:2553 [inline]
 mark_lock_irq kernel/locking/lockdep.c:2747 [inline]
 mark_lock+0xd1b/0x1370 kernel/locking/lockdep.c:3127
 mark_irqflags kernel/locking/lockdep.c:3005 [inline]
 __lock_acquire+0xc62/0x49c0 kernel/locking/lockdep.c:3368
 lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:3903
 __mutex_lock_common kernel/locking/mutex.c:925 [inline]
 __mutex_lock+0xf7/0x1300 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 tpk_write+0x5d/0x340 drivers/char/ttyprintk.c:123
 resync_tnc+0x1b6/0x320 drivers/net/hamradio/6pack.c:522
 call_timer_fn+0x18d/0x720 kernel/time/timer.c:1326
 expire_timers kernel/time/timer.c:1363 [inline]
 __run_timers kernel/time/timer.c:1684 [inline]
 __run_timers kernel/time/timer.c:1652 [inline]
 run_timer_softirq+0x64f/0x16a0 kernel/time/timer.c:1697
 __do_softirq+0x25c/0x921 kernel/softirq.c:292
 invoke_softirq kernel/softirq.c:372 [inline]
 irq_exit+0x180/0x1d0 kernel/softirq.c:412
 exiting_irq arch/x86/include/asm/apic.h:536 [inline]
 smp_apic_timer_interrupt+0x13b/0x550 arch/x86/kernel/apic/apic.c:1094
 apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:893
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
Code: ff ff 48 89 df e8 42 72 56 fa eb 82 e9 07 00 00 00 0f 00 2d 24 b7 5b 00 f4 c3 66 90 e9 07 00 00 00 0f 00 2d 14 b7 5b 00 fb f4 <c3> 90 55 48 89 e5 41 57 41 56 41 55 41 54 53 e8 ce 57 0d fa e8 b9
RSP: 0018:ffffffff88e07cb0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff11e4b74 RBX: ffffffff88e79ec0 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff88e7a73c
RBP: ffffffff88e07ce0 R08: ffffffff88e79ec0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: ffffffff88f25b90 R14: 0000000000000000 R15: ffffffff88e79ec0
 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
 rest_init+0x219/0x222 init/main.c:441
 start_kernel+0x88c/0x8c5 init/main.c:737
 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
Bluetooth: hci0: command 0x1009 tx timeout
BUG: sleeping function called from invalid context at kernel/locking/mutex.c:908
in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
INFO: lockdep is turned off.
Preemption disabled at:
[<ffffffff874b23fd>] schedule_preempt_disabled+0x1d/0x20 kernel/sched/core.c:3618
CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W         4.19.88-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x197/0x210 lib/dump_stack.c:118
 ___might_sleep.cold+0x1bd/0x1f6 kernel/sched/core.c:6191
 __might_sleep+0x95/0x190 kernel/sched/core.c:6144
 __mutex_lock_common kernel/locking/mutex.c:908 [inline]
 __mutex_lock+0xc8/0x1300 kernel/locking/mutex.c:1072
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:1087
 tpk_write+0x5d/0x340 drivers/char/ttyprintk.c:123
 resync_tnc+0x1b6/0x320 drivers/net/hamradio/6pack.c:522
 call_timer_fn+0x18d/0x720 kernel/time/timer.c:1326
 expire_timers kernel/time/timer.c:1363 [inline]
 __run_timers kernel/time/timer.c:1684 [inline]
 __run_timers kernel/time/timer.c:1652 [inline]
 run_timer_softirq+0x64f/0x16a0 kernel/time/timer.c:1697
 __do_softirq+0x25c/0x921 kernel/softirq.c:292
 invoke_softirq kernel/softirq.c:372 [inline]
 irq_exit+0x180/0x1d0 kernel/softirq.c:412
 exiting_irq arch/x86/include/asm/apic.h:536 [inline]
 smp_apic_timer_interrupt+0x13b/0x550 arch/x86/kernel/apic/apic.c:1094
 apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:893
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
Code: ff ff 48 89 df e8 42 72 56 fa eb 82 e9 07 00 00 00 0f 00 2d 24 b7 5b 00 f4 c3 66 90 e9 07 00 00 00 0f 00 2d 14 b7 5b 00 fb f4 <c3> 90 55 48 89 e5 41 57 41 56 41 55 41 54 53 e8 ce 57 0d fa e8 b9
RSP: 0018:ffffffff88e07cb0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff11e4b74 RBX: ffffffff88e79ec0 RCX: 1ffffffff127701c
RDX: dffffc0000000000 RSI: ffffffff81704ece RDI: ffffffff874c270c
RBP: ffffffff88e07ce0 R08: ffffffff88e79ec0 R09: ffffed1015d04733
R10: ffffed1015d04732 R11: ffff8880ae823993 R12: 0000000000000000
R13: ffffffff88f25b90 R14: 0000000000000000 R15: ffffffff88e79ec0
 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
 rest_init+0x219/0x222 init/main.c:441
 start_kernel+0x88c/0x8c5 init/main.c:737
 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
kobject: 'rfkill4' (0000000074c22fd7): kobject_uevent_env
kobject: 'rfkill4' (0000000074c22fd7): fill_kobj_path: path = '/devices/virtual/bluetooth/hci0/rfkill4'
kobject: 'rfkill4' (0000000074c22fd7): kobject_cleanup, parent           (null)
kobject: 'rfkill4' (0000000074c22fd7): calling ktype release
kobject: 'rfkill4': free name
kobject: 'hci0' (000000003b2f3fba): kobject_uevent_env
kobject: 'hci0' (000000003b2f3fba): fill_kobj_path: path = '/devices/virtual/bluetooth/hci0'
kobject: 'bluetooth' (00000000db877332): kobject_cleanup, parent           (null)
kobject: 'bluetooth' (00000000db877332): calling ktype release
kobject: 'bluetooth': free name
kobject: 'hci0' (000000003b2f3fba): kobject_cleanup, parent           (null)
kobject: 'hci0' (000000003b2f3fba): calling ktype release
kobject: 'hci0': free name
[U] è`è`è
kobject: 'rx-0' (000000000c364ab5): kobject_cleanup, parent 00000000ed5d8805
kobject: 'rx-0' (000000000c364ab5): auto cleanup 'remove' event
kobject: 'rx-0' (000000000c364ab5): kobject_uevent_env
kobject: 'rx-0' (000000000c364ab5): fill_kobj_path: path = '/devices/virtual/net/sp0/queues/rx-0'
kobject: 'rx-0' (000000000c364ab5): auto cleanup kobject_del
kobject: 'rx-0' (000000000c364ab5): calling ktype release
kobject: 'rx-0': free name
kobject: 'tx-0' (0000000026652036): kobject_cleanup, parent 00000000ed5d8805
kobject: 'tx-0' (0000000026652036): auto cleanup 'remove' event
kobject: 'tx-0' (0000000026652036): kobject_uevent_env
kobject: 'tx-0' (0000000026652036): fill_kobj_path: path = '/devices/virtual/net/sp0/queues/tx-0'
kobject: 'tx-0' (0000000026652036): auto cleanup kobject_del
kobject: 'tx-0' (0000000026652036): calling ktype release
kobject: 'tx-0': free name
kobject: 'queues' (00000000ed5d8805): kobject_cleanup, parent           (null)
kobject: 'queues' (00000000ed5d8805): calling ktype release
kobject: 'queues' (00000000ed5d8805): kset_release
kobject: 'queues': free name
kobject: 'sp0' (00000000a9aa070c): kobject_uevent_env
kobject: 'sp0' (00000000a9aa070c): fill_kobj_path: path = '/devices/virtual/net/sp0'
kobject: 'sp0' (00000000a9aa070c): kobject_cleanup, parent           (null)
kobject: 'sp0' (00000000a9aa070c): calling ktype release
kobject: 'sp0': free name

Crashes (30):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2019/12/05 20:08 linux-4.19.y fb683b5e3f53 9fd5a512 .config console log report syz C ci2-linux-4-19
2019/12/05 16:20 linux-4.19.y fb683b5e3f53 9fd5a512 .config console log report syz C ci2-linux-4-19
2020/02/05 11:11 linux-4.19.y 32ee7492f104 93e5e335 .config console log report ci2-linux-4-19
2020/02/05 10:27 linux-4.19.y 32ee7492f104 93e5e335 .config console log report ci2-linux-4-19
2020/02/05 06:06 linux-4.19.y 32ee7492f104 93e5e335 .config console log report ci2-linux-4-19
2020/02/03 17:03 linux-4.19.y 32ee7492f104 93e5e335 .config console log report ci2-linux-4-19
2020/02/01 03:23 linux-4.19.y 7cdefde351b6 0eb59c27 .config console log report ci2-linux-4-19
2020/01/31 17:12 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 16:06 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 11:04 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 10:27 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 10:09 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 08:57 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 07:51 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 07:09 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/31 00:14 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/30 23:37 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/30 21:40 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/30 12:34 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/30 05:55 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/29 23:11 linux-4.19.y 7cdefde351b6 5ed23f9a .config console log report ci2-linux-4-19
2020/01/29 15:39 linux-4.19.y 88d6de67e390 5ed23f9a .config console log report ci2-linux-4-19
2020/01/29 15:12 linux-4.19.y 88d6de67e390 c8e81ce4 .config console log report ci2-linux-4-19
2020/01/29 02:19 linux-4.19.y 88d6de67e390 c8e81ce4 .config console log report ci2-linux-4-19
2020/01/28 18:16 linux-4.19.y 88d6de67e390 c8e81ce4 .config console log report ci2-linux-4-19
2020/01/15 16:38 linux-4.19.y db5b9190ff82 069a5a44 .config console log report ci2-linux-4-19
2020/01/03 11:05 linux-4.19.y c7ecf3e3a71c 9dcc1191 .config console log report ci2-linux-4-19
2019/12/29 14:04 linux-4.19.y 672481c2deff af6b8ef8 .config console log report ci2-linux-4-19
2019/12/15 23:06 linux-4.19.y 312017a460d5 eef6e580 .config console log report ci2-linux-4-19
2019/12/05 15:24 linux-4.19.y fb683b5e3f53 9fd5a512 .config console log report ci2-linux-4-19
* Struck through repros no longer work on HEAD.