syzbot


BUG: sleeping function called from invalid context in tpk_write

Status: fixed on 2020/03/06 21:15
Reported-by: syzbot+bfd52992394f1e2fba00@syzkaller.appspotmail.com
Fix commit: ab84fd0d3dc8 ttyprintk: fix a potential deadlock in interrupt context issue
First crash: 1832d, last: 1771d
Fix bisection: fixed by (bisect log) :
commit ab84fd0d3dc83277d6ab7246a6b2cd45ba924367
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.19 BUG: sleeping function called from invalid context in tpk_write C done 30 1771d 1833d 1/1 fixed on 2020/03/06 21:15
upstream BUG: sleeping function called from invalid context in tpk_write kernel C done 12 1789d 1831d 15/28 fixed on 2020/02/18 14:31

Sample crash report:
BUG: sleeping function called from invalid context at kernel/locking/mutex.c:747
in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
1 lock held by swapper/0/0:
 #0:  ((&sp->resync_t)){+.-.}, at: [<ffffffff814fc938>] lockdep_copy_map include/linux/lockdep.h:174 [inline]
 #0:  ((&sp->resync_t)){+.-.}, at: [<ffffffff814fc938>] call_timer_fn+0xc8/0x670 kernel/time/timer.c:1269
Preemption disabled at:
[<ffffffff8664213d>] schedule_preempt_disabled+0x1d/0x20 kernel/sched/core.c:3487
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.14.158-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:17 [inline]
 dump_stack+0x142/0x197 lib/dump_stack.c:58
 ___might_sleep.cold+0x1bd/0x1f6 kernel/sched/core.c:6040
 __might_sleep+0x93/0xb0 kernel/sched/core.c:5993
 __mutex_lock_common kernel/locking/mutex.c:747 [inline]
 __mutex_lock+0xb9/0x1470 kernel/locking/mutex.c:893
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
 tpk_write+0x5d/0x2c0 drivers/char/ttyprintk.c:123
 resync_tnc+0x1bc/0x3d0 drivers/net/hamradio/6pack.c:522
 call_timer_fn+0x161/0x670 kernel/time/timer.c:1279
 expire_timers kernel/time/timer.c:1318 [inline]
 __run_timers kernel/time/timer.c:1636 [inline]
 __run_timers kernel/time/timer.c:1604 [inline]
 run_timer_softirq+0x5b7/0x1520 kernel/time/timer.c:1649
 __do_softirq+0x244/0x9a0 kernel/softirq.c:288
 invoke_softirq kernel/softirq.c:368 [inline]
 irq_exit+0x160/0x1b0 kernel/softirq.c:409
 exiting_irq arch/x86/include/asm/apic.h:648 [inline]
 smp_apic_timer_interrupt+0x146/0x5e0 arch/x86/kernel/apic/apic.c:1102
 apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
RSP: 0018:ffffffff87e07de8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fe2d2c RBX: ffffffff87e76240 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff87e76abc
RBP: ffffffff87e07e10 R08: 1ffffffff1164501 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff87f16950
R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff87e76240
 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+0x6df/0x6fd 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

================================
WARNING: inconsistent lock state
4.14.158-syzkaller #0 Tainted: G        W      
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
 (&tpk_port.port_write_mutex){+.?.}, at: [<ffffffff8356016d>] tpk_write+0x5d/0x2c0 drivers/char/ttyprintk.c:123
{SOFTIRQ-ON-W} state was registered at:
  mark_irqflags kernel/locking/lockdep.c:3086 [inline]
  __lock_acquire+0xc33/0x4620 kernel/locking/lockdep.c:3444
  lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
  __mutex_lock_common kernel/locking/mutex.c:756 [inline]
  __mutex_lock+0xe8/0x1470 kernel/locking/mutex.c:893
  mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
  tpk_write+0x5d/0x2c0 drivers/char/ttyprintk.c:123
  tnc_init drivers/net/hamradio/6pack.c:541 [inline]
  sixpack_open+0x9b2/0xc85 drivers/net/hamradio/6pack.c:643
  tty_ldisc_open.isra.0+0x73/0xb0 drivers/tty/tty_ldisc.c:474
  tty_set_ldisc+0x29a/0x610 drivers/tty/tty_ldisc.c:599
  tiocsetd drivers/tty/tty_io.c:2351 [inline]
  tty_ioctl+0x95b/0x1320 drivers/tty/tty_io.c:2595
  vfs_ioctl fs/ioctl.c:46 [inline]
  file_ioctl fs/ioctl.c:500 [inline]
  do_vfs_ioctl+0x7ae/0x1060 fs/ioctl.c:684
  SYSC_ioctl fs/ioctl.c:701 [inline]
  SyS_ioctl+0x8f/0xc0 fs/ioctl.c:692
  do_syscall_64+0x1e8/0x640 arch/x86/entry/common.c:292
  entry_SYSCALL_64_after_hwframe+0x42/0xb7
irq event stamp: 403338
hardirqs last  enabled at (403338): [<ffffffff86800979>] restore_regs_and_return_to_kernel+0x0/0x27
hardirqs last disabled at (403337): [<ffffffff868008d1>] common_interrupt+0x91/0x96 arch/x86/entry/entry_64.S:576
softirqs last  enabled at (403236): [<ffffffff8138e38c>] _local_bh_enable+0x1c/0x30 kernel/softirq.c:159
softirqs last disabled at (403237): [<ffffffff81390640>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (403237): [<ffffffff81390640>] irq_exit+0x160/0x1b0 kernel/softirq.c:409

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:  ((&sp->resync_t)){+.-.}, at: [<ffffffff814fc938>] lockdep_copy_map include/linux/lockdep.h:174 [inline]
 #0:  ((&sp->resync_t)){+.-.}, at: [<ffffffff814fc938>] call_timer_fn+0xc8/0x670 kernel/time/timer.c:1269

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W       4.14.158-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:17 [inline]
 dump_stack+0x142/0x197 lib/dump_stack.c:58
 print_usage_bug.cold+0x330/0x42a kernel/locking/lockdep.c:2585
 valid_state kernel/locking/lockdep.c:2598 [inline]
 mark_lock_irq kernel/locking/lockdep.c:2792 [inline]
 mark_lock+0xdbd/0x1240 kernel/locking/lockdep.c:3190
 mark_irqflags kernel/locking/lockdep.c:3068 [inline]
 __lock_acquire+0xb57/0x4620 kernel/locking/lockdep.c:3444
 lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
 __mutex_lock_common kernel/locking/mutex.c:756 [inline]
 __mutex_lock+0xe8/0x1470 kernel/locking/mutex.c:893
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
 tpk_write+0x5d/0x2c0 drivers/char/ttyprintk.c:123
 resync_tnc+0x1bc/0x3d0 drivers/net/hamradio/6pack.c:522
 call_timer_fn+0x161/0x670 kernel/time/timer.c:1279
 expire_timers kernel/time/timer.c:1318 [inline]
 __run_timers kernel/time/timer.c:1636 [inline]
 __run_timers kernel/time/timer.c:1604 [inline]
 run_timer_softirq+0x5b7/0x1520 kernel/time/timer.c:1649
 __do_softirq+0x244/0x9a0 kernel/softirq.c:288
 invoke_softirq kernel/softirq.c:368 [inline]
 irq_exit+0x160/0x1b0 kernel/softirq.c:409
 exiting_irq arch/x86/include/asm/apic.h:648 [inline]
 smp_apic_timer_interrupt+0x146/0x5e0 arch/x86/kernel/apic/apic.c:1102
 apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
RSP: 0018:ffffffff87e07de8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fe2d2c RBX: ffffffff87e76240 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff87e76abc
RBP: ffffffff87e07e10 R08: 1ffffffff1164501 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff87f16950
R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff87e76240
 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+0x6df/0x6fd 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
[U] `è
BUG: sleeping function called from invalid context at kernel/locking/mutex.c:747
in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
INFO: lockdep is turned off.
Preemption disabled at:
[<ffffffff8664213d>] schedule_preempt_disabled+0x1d/0x20 kernel/sched/core.c:3487
CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W       4.14.158-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:17 [inline]
 dump_stack+0x142/0x197 lib/dump_stack.c:58
 ___might_sleep.cold+0x1bd/0x1f6 kernel/sched/core.c:6040
 __might_sleep+0x93/0xb0 kernel/sched/core.c:5993
 __mutex_lock_common kernel/locking/mutex.c:747 [inline]
 __mutex_lock+0xb9/0x1470 kernel/locking/mutex.c:893
 mutex_lock_nested+0x16/0x20 kernel/locking/mutex.c:908
 tpk_write+0x5d/0x2c0 drivers/char/ttyprintk.c:123
 resync_tnc+0x1bc/0x3d0 drivers/net/hamradio/6pack.c:522
 call_timer_fn+0x161/0x670 kernel/time/timer.c:1279
 expire_timers kernel/time/timer.c:1318 [inline]
 __run_timers kernel/time/timer.c:1636 [inline]
 __run_timers kernel/time/timer.c:1604 [inline]
 run_timer_softirq+0x5b7/0x1520 kernel/time/timer.c:1649
 __do_softirq+0x244/0x9a0 kernel/softirq.c:288
 invoke_softirq kernel/softirq.c:368 [inline]
 irq_exit+0x160/0x1b0 kernel/softirq.c:409
 exiting_irq arch/x86/include/asm/apic.h:648 [inline]
 smp_apic_timer_interrupt+0x146/0x5e0 arch/x86/kernel/apic/apic.c:1102
 apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
RSP: 0018:ffffffff87e07de8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fe2d2c RBX: ffffffff87e76240 RCX: 1ffffffff1066d00
RDX: dffffc0000000000 RSI: ffffffff8703f880 RDI: ffffffff86651eba
RBP: ffffffff87e07e10 R08: 1ffffffff1164501 R09: ffffffff81534195
R10: 0000000000000000 R11: ffffffff87e76240 R12: ffffffff87f16950
R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff87e76240
 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+0x6df/0x6fd 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
[U] `è

Crashes (10):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2019/12/05 21:56 linux-4.14.y a844dc4c5442 9fd5a512 .config console log report syz C ci2-linux-4-14
2019/12/05 19:44 linux-4.14.y a844dc4c5442 9fd5a512 .config console log report syz C ci2-linux-4-14
2020/02/05 11:50 linux-4.14.y 9fa690a2a016 93e5e335 .config console log report ci2-linux-4-14
2020/02/04 05:11 linux-4.14.y 9fa690a2a016 93e5e335 .config console log report ci2-linux-4-14
2020/02/03 16:22 linux-4.14.y 9fa690a2a016 93e5e335 .config console log report ci2-linux-4-14
2020/01/24 02:59 linux-4.14.y 8bac50406cca 11ebf937 .config console log report ci2-linux-4-14
2019/12/26 07:11 linux-4.14.y e1f7d50ae3a3 be5c2c81 .config console log report ci2-linux-4-14
2019/12/26 03:37 linux-4.14.y e1f7d50ae3a3 be5c2c81 .config console log report ci2-linux-4-14
2019/12/11 04:22 linux-4.14.y a844dc4c5442 101194eb .config console log report ci2-linux-4-14
2019/12/07 18:03 linux-4.14.y a844dc4c5442 85f26751 .config console log report ci2-linux-4-14
* Struck through repros no longer work on HEAD.