WARNING in switched_from_dl

4 views
Skip to first unread message

syzbot

unread,
Apr 11, 2019, 8:00:56 PM4/11/19
to syzkaller-a...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 47350a9f ANDROID: x86_64_cuttlefish_defconfig: Enable lz4 ..
git tree: android-4.14
console output: https://syzkaller.appspot.com/x/log.txt?x=14afc951400000
kernel config: https://syzkaller.appspot.com/x/.config?x=10d236078f3378a3
dashboard link: https://syzkaller.appspot.com/bug?extid=f6170b3938e42ac8116d
compiler: gcc (GCC) 8.0.1 20180413 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=11117d1e400000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=17e75e0a400000

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

random: sshd: uninitialized urandom read (32 bytes read)
random: sshd: uninitialized urandom read (32 bytes read)
random: sshd: uninitialized urandom read (32 bytes read)
dl_rq->running_bw > dl_rq->this_bw
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1981 at kernel/sched/deadline.c:125 sub_rq_bw
kernel/sched/deadline.c:125 [inline]
WARNING: CPU: 0 PID: 1981 at kernel/sched/deadline.c:125
switched_from_dl.cold.25+0x5b/0x62 kernel/sched/deadline.c:2232
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 1981 Comm: syz-executor145 Not tainted 4.14.67+ #1
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0xb9/0x11b lib/dump_stack.c:53
panic+0x1bf/0x3a4 kernel/panic.c:181
__warn.cold.7+0x148/0x185 kernel/panic.c:542
report_bug+0x1f7/0x26c lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:177 [inline]
do_error_trap+0x1ba/0x2c0 arch/x86/kernel/traps.c:295
invalid_op+0x18/0x40 arch/x86/entry/entry_64.S:944
RIP: 0010:sub_rq_bw kernel/sched/deadline.c:125 [inline]
RIP: 0010:switched_from_dl.cold.25+0x5b/0x62 kernel/sched/deadline.c:2232
RSP: 0018:ffff8801b90b7d18 EFLAGS: 00010082
RAX: 0000000000000022 RBX: ffff8801ba4cc680 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff8801baa89f78
RBP: ffff8801d792a240 R08: 0000000000000001 R09: 0000000000000000
R10: ffff8801baa8a028 R11: 0000000000000001 R12: ffff8801ba4cc6dc
R13: 0000000000000000 R14: ffff8801d792ab50 R15: 0000000000099179
check_class_changed kernel/sched/core.c:871 [inline]
__sched_setscheduler+0x9a1/0x2800 kernel/sched/core.c:4295
sched_setattr kernel/sched/core.c:4348 [inline]
SYSC_sched_setattr kernel/sched/core.c:4519 [inline]
SyS_sched_setattr+0x22c/0x370 kernel/sched/core.c:4498
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x4456e9
RSP: 002b:00007f2c3d1d2da8 EFLAGS: 00000293 ORIG_RAX: 000000000000013a
RAX: ffffffffffffffda RBX: 00000000006dac28 RCX: 00000000004456e9
RDX: 0000000000000000 RSI: 0000000020000280 RDI: 00000000000007bc
RBP: 00000000006dac20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 00000000006dac2c
R13: 0000840000000002 R14: 00007f2c3d1d39c0 R15: 00000000006dad2c

======================================================
WARNING: possible circular locking dependency detected
4.14.67+ #1 Not tainted
------------------------------------------------------
syz-executor145/1981 is trying to acquire lock:
(&port_lock_key){-...}, at: [<ffffffff8e15268f>]
serial8250_console_write+0x6af/0x800
drivers/tty/serial/8250/8250_port.c:3232

but task is already holding lock:
(&rq->lock){-.-.}, at: [<ffffffff8d5610b9>] task_rq_lock+0xc9/0x340
kernel/sched/core.c:126

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #3 (&rq->lock){-.-.}:
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
rq_lock kernel/sched/sched.h:1835 [inline]
task_fork_fair+0x59/0x590 kernel/sched/fair.c:11391
sched_fork+0x48b/0xd30 kernel/sched/core.c:2459
copy_process.part.6+0x120d/0x6490 kernel/fork.c:1730
copy_process kernel/fork.c:1571 [inline]
_do_fork+0x1c2/0xd50 kernel/fork.c:2052
kernel_thread+0x2f/0x40 kernel/fork.c:2116
rest_init+0x22/0x2a0 init/main.c:401
start_kernel+0x6fb/0x739 init/main.c:710
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:239

-> #2 (&p->pi_lock){-.-.}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x41/0x50 kernel/locking/spinlock.c:160
try_to_wake_up+0x95/0x1230 kernel/sched/core.c:2030
__wake_up_common+0x109/0x5a0 kernel/sched/wait.c:97
__wake_up_common_lock+0xc5/0x120 kernel/sched/wait.c:125
tty_port_default_wakeup+0x26/0x40 drivers/tty/tty_port.c:49
serial8250_tx_chars+0x417/0xa70
drivers/tty/serial/8250/8250_port.c:1810
serial8250_handle_irq.part.15+0x1b1/0x1f0
drivers/tty/serial/8250/8250_port.c:1883
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1869
[inline]
serial8250_default_handle_irq+0x9b/0x110
drivers/tty/serial/8250/8250_port.c:1899
serial8250_interrupt+0xea/0x1a0
drivers/tty/serial/8250/8250_core.c:129
__handle_irq_event_percpu+0xf8/0x770 kernel/irq/handle.c:147
handle_irq_event_percpu+0x76/0x150 kernel/irq/handle.c:187
handle_irq_event+0xa1/0x12d kernel/irq/handle.c:204
handle_edge_irq+0x1f0/0x7f0 kernel/irq/chip.c:770
generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
handle_irq+0x242/0x328 arch/x86/kernel/irq_64.c:78
do_IRQ+0x7d/0x1b0 arch/x86/kernel/irq.c:230
ret_from_intr+0x0/0x22
arch_local_irq_restore arch/x86/include/asm/paravirt.h:778 [inline]
__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160
[inline]
_raw_spin_unlock_irqrestore+0x59/0x70 kernel/locking/spinlock.c:192
spin_unlock_irqrestore include/linux/spinlock.h:372 [inline]
uart_write+0x2a7/0x480 drivers/tty/serial/serial_core.c:604
process_output_block drivers/tty/n_tty.c:582 [inline]
n_tty_write+0x4f5/0xda0 drivers/tty/n_tty.c:2319
do_tty_write drivers/tty/tty_io.c:957 [inline]
tty_write+0x397/0x810 drivers/tty/tty_io.c:1041
redirected_tty_write+0x9a/0xa0 drivers/tty/tty_io.c:1062
__vfs_write+0xf4/0x5c0 fs/read_write.c:482
vfs_write+0x17f/0x4d0 fs/read_write.c:546
SYSC_write fs/read_write.c:593 [inline]
SyS_write+0xc2/0x1a0 fs/read_write.c:585
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #1 (&tty->write_wait){-...}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x41/0x50 kernel/locking/spinlock.c:160
__wake_up_common_lock+0xaa/0x120 kernel/sched/wait.c:124
tty_port_default_wakeup+0x26/0x40 drivers/tty/tty_port.c:49
serial8250_tx_chars+0x417/0xa70
drivers/tty/serial/8250/8250_port.c:1810
serial8250_handle_irq.part.15+0x1b1/0x1f0
drivers/tty/serial/8250/8250_port.c:1883
serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1869
[inline]
serial8250_default_handle_irq+0x9b/0x110
drivers/tty/serial/8250/8250_port.c:1899
serial8250_interrupt+0xea/0x1a0
drivers/tty/serial/8250/8250_core.c:129
__handle_irq_event_percpu+0xf8/0x770 kernel/irq/handle.c:147
handle_irq_event_percpu+0x76/0x150 kernel/irq/handle.c:187
handle_irq_event+0xa1/0x12d kernel/irq/handle.c:204
handle_edge_irq+0x1f0/0x7f0 kernel/irq/chip.c:770
generic_handle_irq_desc include/linux/irqdesc.h:158 [inline]
handle_irq+0x242/0x328 arch/x86/kernel/irq_64.c:78
do_IRQ+0x7d/0x1b0 arch/x86/kernel/irq.c:230
ret_from_intr+0x0/0x22
arch_local_irq_restore arch/x86/include/asm/paravirt.h:778 [inline]
__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160
[inline]
_raw_spin_unlock_irqrestore+0x59/0x70 kernel/locking/spinlock.c:192
spin_unlock_irqrestore include/linux/spinlock.h:372 [inline]
uart_write+0x2a7/0x480 drivers/tty/serial/serial_core.c:604
process_output_block drivers/tty/n_tty.c:582 [inline]
n_tty_write+0x4f5/0xda0 drivers/tty/n_tty.c:2319
do_tty_write drivers/tty/tty_io.c:957 [inline]
tty_write+0x397/0x810 drivers/tty/tty_io.c:1041
redirected_tty_write+0x9a/0xa0 drivers/tty/tty_io.c:1062
__vfs_write+0xf4/0x5c0 fs/read_write.c:482
vfs_write+0x17f/0x4d0 fs/read_write.c:546
SYSC_write fs/read_write.c:593 [inline]
SyS_write+0xc2/0x1a0 fs/read_write.c:585
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #0 (&port_lock_key){-...}:
lock_acquire+0x10f/0x380 kernel/locking/lockdep.c:3991
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x41/0x50 kernel/locking/spinlock.c:160
serial8250_console_write+0x6af/0x800
drivers/tty/serial/8250/8250_port.c:3232
call_console_drivers kernel/printk/printk.c:1574 [inline]
console_unlock+0x5b9/0xb50 kernel/printk/printk.c:2233
vprintk_emit+0x241/0x4e0 kernel/printk/printk.c:1757
vprintk_func+0x58/0x136 kernel/printk/printk_safe.c:385
printk+0xa7/0xcf kernel/printk/printk.c:1829
__warn+0x36/0x50 kernel/panic.c:521
report_bug+0x1f7/0x26c lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:177 [inline]
do_error_trap+0x1ba/0x2c0 arch/x86/kernel/traps.c:295
invalid_op+0x18/0x40 arch/x86/entry/entry_64.S:944
sub_rq_bw kernel/sched/deadline.c:125 [inline]
switched_from_dl.cold.25+0x5b/0x62 kernel/sched/deadline.c:2232
check_class_changed kernel/sched/core.c:871 [inline]
__sched_setscheduler+0x9a1/0x2800 kernel/sched/core.c:4295
sched_setattr kernel/sched/core.c:4348 [inline]
SYSC_sched_setattr kernel/sched/core.c:4519 [inline]
SyS_sched_setattr+0x22c/0x370 kernel/sched/core.c:4498
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7

other info that might help us debug this:

Chain exists of:
&port_lock_key --> &p->pi_lock --> &rq->lock

Possible unsafe locking scenario:

CPU0 CPU1
---- ----
lock(&rq->lock);
lock(&p->pi_lock);
lock(&rq->lock);
lock(&port_lock_key);

*** DEADLOCK ***

4 locks held by syz-executor145/1981:
#0: (rcu_read_lock){....}, at: [<ffffffff8d571e90>] SYSC_sched_setattr
kernel/sched/core.c:4512 [inline]
#0: (rcu_read_lock){....}, at: [<ffffffff8d571e90>]
SyS_sched_setattr+0x1c0/0x370 kernel/sched/core.c:4498
#1: (&p->pi_lock){-.-.}, at: [<ffffffff8d561058>] task_rq_lock+0x68/0x340
kernel/sched/core.c:124
#2: (&rq->lock){-.-.}, at: [<ffffffff8d5610b9>] task_rq_lock+0xc9/0x340
kernel/sched/core.c:126
#3: (console_lock){+.+.}, at: [<ffffffff8d61d8c3>]
vprintk_emit+0x233/0x4e0 kernel/printk/printk.c:1756

stack backtrace:
CPU: 0 PID: 1981 Comm: syz-executor145 Not tainted 4.14.67+ #1
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0xb9/0x11b lib/dump_stack.c:53
print_circular_bug.isra.18.cold.43+0x2d3/0x40c
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+0x2ff9/0x4320 kernel/locking/lockdep.c:3487
lock_acquire+0x10f/0x380 kernel/locking/lockdep.c:3991
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x41/0x50 kernel/locking/spinlock.c:160
serial8250_console_write+0x6af/0x800
drivers/tty/serial/8250/8250_port.c:3232
call_console_drivers kernel/printk/printk.c:1574 [inline]
console_unlock+0x5b9/0xb50 kernel/printk/printk.c:2233
vprintk_emit+0x241/0x4e0 kernel/printk/printk.c:1757
vprintk_func+0x58/0x136 kernel/printk/printk_safe.c:385
printk+0xa7/0xcf kernel/printk/printk.c:1829
__warn+0x36/0x50 kernel/panic.c:521
report_bug+0x1f7/0x26c lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:177 [inline]
do_error_trap+0x1ba/0x2c0 arch/x86/kernel/traps.c:295
invalid_op+0x18/0x40 arch/x86/entry/entry_64.S:944
RIP: 0010:sub_rq_bw kernel/sched/deadline.c:125 [inline]
RIP: 0010:switched_from_dl.cold.25+0x5b/0x62 kernel/sched/deadline.c:2232
RSP: 0018:ffff8801b90b7d18 EFLAGS: 00010082
RAX: 0000000000000022 RBX: ffff8801ba4cc680 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff8801baa89f78
RBP: ffff8801d792a240 R08: 0000000000000001 R09: 0000000000000000
R10: ffff8801baa8a028 R11: 0000000000000001 R12: ffff8801ba4cc6dc
R13: 0000000000000000 R14: ffff8801d792ab50 R15: 0000000000099179
check_class_changed kernel/sched/core.c:871 [inline]
__sched_setscheduler+0x9a1/0x2800 kernel/sched/core.c:4295
sched_setattr kernel/sched/core.c:4348 [inline]
SYSC_sched_setattr kernel/sched/core.c:4519 [inline]
SyS_sched_setattr+0x22c/0x370 kernel/sched/core.c:4498
do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x4456e9
RSP: 002b:00007f2c3d1d2da8 EFLAGS: 00000293 ORIG_RAX: 000000000000013a
RAX: ffffffffffffffda RBX: 00000000006dac28 RCX: 00000000004456e9
RDX: 0000000000000000 RSI: 0000000020000280 RDI: 00000000000007bc
RBP: 00000000006dac20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 00000000006dac2c
R13: 0000840000000002 R14: 00007f2c3d1d39c0 R15: 00000000006dad2c
Shutting down cpus with NMI
Dumping ftrace buffer:
(ftrace buffer empty)
Kernel Offset: 0xc400000 from 0xffffffff81000000 (relocation range:
0xffffffff80000000-0xffffffffbfffffff)
Rebooting in 86400 seconds..


---
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 can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches
Reply all
Reply to author
Forward
0 new messages