BUG: sleeping function called from invalid context at kernel/locking/rwsem.c:LINE

18 views
Skip to first unread message

syzbot

unread,
Apr 14, 2019, 4:51:26 AM4/14/19
to syzkaller-a...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 8fe42840 Merge 4.9.141 into android-4.9
git tree: android-4.9
console output: https://syzkaller.appspot.com/x/log.txt?x=110f53fd400000
kernel config: https://syzkaller.appspot.com/x/.config?x=22a5ba9f73b6da1d
dashboard link: https://syzkaller.appspot.com/bug?extid=e126f9b8391e457da733
compiler: gcc (GCC) 8.0.1 20180413 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=126fcb77400000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1059f1e7400000

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

random: sshd: uninitialized urandom read (32 bytes read)
random: crng init done
syz-executor632 (2068) used greatest stack depth: 23784 bytes left
BUG: sleeping function called from invalid context at
kernel/locking/rwsem.c:51
in_atomic(): 1, irqs_disabled(): 0, pid: 0, name: swapper/0
no locks held by swapper/0/0.
Preemption disabled at:[ 36.849289] [<ffffffff828094ad>]
schedule_preempt_disabled+0x1d/0x20 kernel/sched/core.c:3587
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.9.141+ #1
ffff8801db607a20 ffffffff81b42e79 ffffffff828094ad 0000000000000000
0000000000000101 ffffffff83029180 ffffffff83029180 ffff8801db607a58
ffffffff813f9ecf ffffffff83029180 ffffffff82a4fa80 0000000000000033
Call Trace:
<IRQ> [ 36.890926] [<ffffffff81b42e79>] __dump_stack
lib/dump_stack.c:15 [inline]
<IRQ> [ 36.890926] [<ffffffff81b42e79>] dump_stack+0xc1/0x128
lib/dump_stack.c:51
[<ffffffff813f9ecf>] ___might_sleep.cold.31+0x18a/0x1fc
kernel/sched/core.c:7988
[<ffffffff81167c85>] __might_sleep+0x95/0x1a0 kernel/sched/core.c:7945
[<ffffffff828116d1>] down_write+0x21/0xa0 kernel/locking/rwsem.c:51
[<ffffffff8158b831>] inode_lock include/linux/fs.h:766 [inline]
[<ffffffff8158b831>] __generic_file_fsync+0xc1/0x1a0 fs/libfs.c:978
[<ffffffff816b5209>] ext4_sync_file+0x659/0x10a0 fs/ext4/fsync.c:116
[<ffffffff815b195c>] vfs_fsync_range+0x10c/0x260 fs/sync.c:195
[<ffffffff815cd622>] generic_write_sync include/linux/fs.h:2607 [inline]
[<ffffffff815cd622>] dio_complete+0x512/0x6c0 fs/direct-io.c:282
[<ffffffff815cd8ec>] dio_bio_end_aio+0x11c/0x370 fs/direct-io.c:323
[<ffffffff81ab5f75>] bio_endio+0x1a5/0x1f0 block/bio.c:1781
[<ffffffff81ad65d8>] req_bio_endio block/blk-core.c:157 [inline]
[<ffffffff81ad65d8>] blk_update_request+0x248/0x9b0 block/blk-core.c:2628
[<ffffffff81e1c7ed>] scsi_end_request+0x9d/0x5c0
drivers/scsi/scsi_lib.c:606
[<ffffffff81e257f3>] scsi_io_completion+0x273/0x17a0
drivers/scsi/scsi_lib.c:829
[<ffffffff81e0871a>] scsi_finish_command+0x3ba/0x530
drivers/scsi/scsi.c:607
[<ffffffff81e23d20>] scsi_softirq_done+0x250/0x360
drivers/scsi/scsi_lib.c:1567
[<ffffffff81af449d>] blk_done_softirq+0x27d/0x3e0 block/blk-softirq.c:35
[<ffffffff8281cb9e>] __do_softirq+0x20e/0x964 kernel/softirq.c:288
[<ffffffff810efdbc>] invoke_softirq kernel/softirq.c:368 [inline]
[<ffffffff810efdbc>] irq_exit+0x11c/0x150 kernel/softirq.c:409
[<ffffffff82819b9d>] exiting_irq arch/x86/include/asm/apic.h:669 [inline]
[<ffffffff82819b9d>] do_IRQ+0x10d/0x1c0 arch/x86/kernel/irq.c:252
[<ffffffff8281819d>] common_interrupt+0x9d/0x9d
arch/x86/entry/entry_64.S:461
<EOI> [ 37.098554] [<ffffffff82816496>] ? native_safe_halt+0x6/0x10
arch/x86/include/asm/irqflags.h:56
[<ffffffff828159f5>] arch_safe_halt arch/x86/include/asm/paravirt.h:104
[inline]
[<ffffffff828159f5>] default_idle+0x55/0x360 arch/x86/kernel/process.c:437
[<ffffffff81068a40>] arch_cpu_idle+0x10/0x20 arch/x86/kernel/process.c:428
[<ffffffff828168f5>] default_idle_call+0x45/0x60 kernel/sched/idle.c:97
[<ffffffff811f0a85>] cpuidle_idle_call kernel/sched/idle.c:155 [inline]
[<ffffffff811f0a85>] cpu_idle_loop kernel/sched/idle.c:248 [inline]
[<ffffffff811f0a85>] cpu_startup_entry+0x2b5/0x380 kernel/sched/idle.c:303
[<ffffffff82804eac>] rest_init+0x183/0x189 init/main.c:409
[<ffffffff8341a91b>] start_kernel+0x5fb/0x62f init/main.c:664
[<ffffffff8341929a>] x86_64_start_reservations+0x29/0x2b
arch/x86/kernel/head64.c:196
[<ffffffff834193d6>] x86_64_start_kernel+0x13a/0x15d
arch/x86/kernel/head64.c:177

=================================
[ INFO: inconsistent lock state ]
4.9.141+ #1 Tainted: G W
---------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&sb->s_type->i_mutex_key#9){+.?.+.}, at: [<ffffffff8158b831>] inode_lock
include/linux/fs.h:766 [inline]
(&sb->s_type->i_mutex_key#9){+.?.+.}, at: [<ffffffff8158b831>]
__generic_file_fsync+0xc1/0x1a0 fs/libfs.c:978
mark_irqflags kernel/locking/lockdep.c:2941 [inline]
__lock_acquire+0xbdd/0x4a10 kernel/locking/lockdep.c:3302
lock_acquire+0x130/0x3e0 kernel/locking/lockdep.c:3756
down_write+0x41/0xa0 kernel/locking/rwsem.c:52
inode_lock include/linux/fs.h:766 [inline]
bprm_fill_uid fs/exec.c:1506 [inline]
prepare_binprm+0x2b7/0x750 fs/exec.c:1540
do_execveat_common.isra.14+0xe9f/0x1ed0 fs/exec.c:1766
do_execve fs/exec.c:1829 [inline]
SYSC_execve fs/exec.c:1910 [inline]
SyS_execve+0x42/0x50 fs/exec.c:1905
do_syscall_64+0x19f/0x550 arch/x86/entry/common.c:285
entry_SYSCALL_64_after_swapgs+0x5d/0xdb
irq event stamp: 283986
hardirqs last enabled at (283986): [<ffffffff82818226>]
restore_regs_and_iret+0x0/0x1d
hardirqs last disabled at (283985): [<ffffffff82819028>]
apic_timer_interrupt+0x98/0xb0 arch/x86/entry/entry_64.S:648
softirqs last enabled at (283948): [<ffffffff810ef61c>]
_local_bh_enable+0x1c/0x50 kernel/softirq.c:159
softirqs last disabled at (283949): [<ffffffff810efdbc>] invoke_softirq
kernel/softirq.c:368 [inline]
softirqs last disabled at (283949): [<ffffffff810efdbc>]
irq_exit+0x11c/0x150 kernel/softirq.c:409

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

CPU0
----
lock(&sb->s_type->i_mutex_key#9);
<Interrupt>
lock(&sb->s_type->i_mutex_key#9);

*** DEADLOCK ***

no locks held by swapper/0/0.

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W 4.9.141+ #1
ffff8801db607790 ffffffff81b42e79 ffffffff83029180 ffffffff83cab370
ffffffff83029a30 ffffffff83029a50 ffffffff84244d40 ffff8801db607808
ffffffff81400780 0000000000000001 ffffffff00000001 0000000000000000
Call Trace:
<IRQ> [ 37.376862] [<ffffffff81b42e79>] __dump_stack
lib/dump_stack.c:15 [inline]
<IRQ> [ 37.376862] [<ffffffff81b42e79>] dump_stack+0xc1/0x128
lib/dump_stack.c:51
[<ffffffff81400780>] print_usage_bug.cold.40+0x44e/0x57e
kernel/locking/lockdep.c:2387
[<ffffffff81205d42>] valid_state kernel/locking/lockdep.c:2400 [inline]
[<ffffffff81205d42>] mark_lock_irq kernel/locking/lockdep.c:2602 [inline]
[<ffffffff81205d42>] mark_lock+0x2f2/0x1290 kernel/locking/lockdep.c:3065
[<ffffffff81208434>] mark_irqflags kernel/locking/lockdep.c:2923 [inline]
[<ffffffff81208434>] __lock_acquire+0x1084/0x4a10
kernel/locking/lockdep.c:3302
[<ffffffff8120c8d0>] lock_acquire+0x130/0x3e0 kernel/locking/lockdep.c:3756
[<ffffffff828116f1>] down_write+0x41/0xa0 kernel/locking/rwsem.c:52
[<ffffffff8158b831>] inode_lock include/linux/fs.h:766 [inline]
[<ffffffff8158b831>] __generic_file_fsync+0xc1/0x1a0 fs/libfs.c:978
[<ffffffff816b5209>] ext4_sync_file+0x659/0x10a0 fs/ext4/fsync.c:116
[<ffffffff815b195c>] vfs_fsync_range+0x10c/0x260 fs/sync.c:195
[<ffffffff815cd622>] generic_write_sync include/linux/fs.h:2607 [inline]
[<ffffffff815cd622>] dio_complete+0x512/0x6c0 fs/direct-io.c:282
[<ffffffff815cd8ec>] dio_bio_end_aio+0x11c/0x370 fs/direct-io.c:323
[<ffffffff81ab5f75>] bio_endio+0x1a5/0x1f0 block/bio.c:1781
[<ffffffff81ad65d8>] req_bio_endio block/blk-core.c:157 [inline]
[<ffffffff81ad65d8>] blk_update_request+0x248/0x9b0 block/blk-core.c:2628
[<ffffffff81e1c7ed>] scsi_end_request+0x9d/0x5c0
drivers/scsi/scsi_lib.c:606
[<ffffffff81e257f3>] scsi_io_completion+0x273/0x17a0
drivers/scsi/scsi_lib.c:829
[<ffffffff81e0871a>] scsi_finish_command+0x3ba/0x530
drivers/scsi/scsi.c:607
[<ffffffff81e23d20>] scsi_softirq_done+0x250/0x360
drivers/scsi/scsi_lib.c:1567
[<ffffffff81af449d>] blk_done_softirq+0x27d/0x3e0 block/blk-softirq.c:35
[<ffffffff8281cb9e>] __do_softirq+0x20e/0x964 kernel/softirq.c:288
[<ffffffff810efdbc>] invoke_softirq kernel/softirq.c:368 [inline]
[<ffffffff810efdbc>] irq_exit+0x11c/0x150 kernel/softirq.c:409
[<ffffffff82819b9d>] exiting_irq arch/x86/include/asm/apic.h:669 [inline]
[<ffffffff82819b9d>] do_IRQ+0x10d/0x1c0 arch/x86/kernel/irq.c:252
[<ffffffff8281819d>] common_interrupt+0x9d/0x9d
arch/x86/entry/entry_64.S:461
<EOI> [ 37.657761] [<ffffffff82816496>] ? native_safe_halt+0x6/0x10
arch/x86/include/asm/irqflags.h:56
[<ffffffff828159f5>] arch_safe_halt arch/x86/include/asm/paravirt.h:104
[inline]
[<ffffffff828159f5>] default_idle+0x55/0x360 arch/x86/kernel/process.c:437
[<ffffffff81068a40>] arch_cpu_idle+0x10/0x20 arch/x86/kernel/process.c:428
[<ffffffff828168f5>] default_idle_call+0x45/0x60 kernel/sched/idle.c:97
[<ffffffff811f0a85>] cpuidle_idle_call kernel/sched/idle.c:155 [inline]
[<ffffffff811f0a85>] cpu_idle_loop kernel/sched/idle.c:248 [inline]
[<ffffffff811f0a85>] cpu_startup_entry+0x2b5/0x380 kernel/sched/idle.c:303
[<ffffffff82804eac>] rest_init+0x183/0x189 init/main.c:409
[<ffffffff8341a91b>] start_kernel+0x5fb/0x62f init/main.c:664
[<ffffffff8341929a>] x86_64_start_reservations+0x29/0x2b
arch/x86/kernel/head64.c:196
[<ffffffff834193d6>] x86_64_start_kernel+0x13a/0x15d
arch/x86/kernel/head64.c:177
BUG: scheduling while atomic: swapper/0/0/0x00000102
INFO: lockdep is turned off.
Modules linked in:
Preemption disabled at:[ 37.754120] [<ffffffff828094ad>]
schedule_preempt_disabled+0x1d/0x20 kernel/sched/core.c:3587


---
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