INFO: task hung in blkdev_issue_flush

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit: aec3002d Linux 4.19.56
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=15c8716da00000
kernel config: https://syzkaller.appspot.com/x/.config?x=48b721ea0070d1cd
dashboard link: https://syzkaller.appspot.com/bug?extid=b8dab3b2459def923263
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+b8dab3...@syzkaller.appspotmail.com

block nbd0: Receive control failed (result -104)
block nbd0: shutting down sockets
block nbd0: Device being setup by another task
INFO: task syz-executor.4:24079 blocked for more than 140 seconds.
Not tainted 4.19.56 #28
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.4 D28792 24079 8039 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2826 [inline]
__schedule+0x80d/0x1c70 kernel/sched/core.c:3474
schedule+0x92/0x1c0 kernel/sched/core.c:3518
schedule_timeout+0x8c8/0xfc0 kernel/time/timer.c:1780
io_schedule_timeout+0x26/0x80 kernel/sched/core.c:5129
do_wait_for_common kernel/sched/completion.c:83 [inline]
__wait_for_common kernel/sched/completion.c:104 [inline]
wait_for_common_io kernel/sched/completion.c:121 [inline]
wait_for_completion_io+0x29c/0x440 kernel/sched/completion.c:169
submit_bio_wait+0x11d/0x1c0 block/bio.c:931
blkdev_issue_flush+0x20b/0x300 block/blk-flush.c:553
blkdev_fsync+0x95/0xd0 fs/block_dev.c:647
vfs_fsync_range+0x141/0x230 fs/sync.c:197
vfs_fsync fs/sync.c:211 [inline]
do_fsync+0x54/0xa0 fs/sync.c:221
__do_sys_fdatasync fs/sync.c:234 [inline]
__se_sys_fdatasync fs/sync.c:232 [inline]
__x64_sys_fdatasync+0x36/0x50 fs/sync.c:232
do_syscall_64+0xfd/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4597c9
Code: Bad RIP value.
RSP: 002b:00007ff531ccac78 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00000000004597c9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000003
RBP: 000000000075bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ff531ccb6d4
R13: 00000000004c005d R14: 00000000004d1e50 R15: 00000000ffffffff

Showing all locks held in the system:
1 lock held by khungtaskd/1034:
#0: 00000000abc9b428 (rcu_read_lock){....}, at:
debug_show_all_locks+0x5f/0x27e kernel/locking/lockdep.c:4435
1 lock held by rsyslogd/7857:
#0: 00000000ca5ab141 (&f->f_pos_lock){+.+.}, at: __fdget_pos+0xee/0x110
fs/file.c:767
2 locks held by getty/7979:
#0: 00000000b9ee3f7b (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 0000000075aaf9f3 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7980:
#0: 00000000de489c86 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 000000009ba59a46 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7981:
#0: 000000000fdb88d0 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 0000000033fd414d (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7982:
#0: 00000000fb3bd1c3 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 000000007e138fba (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7983:
#0: 000000005bd8faa2 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 000000003fa029dd (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7984:
#0: 000000000aa91ec3 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 000000000387888f (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7985:
#0: 000000004ed14514 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 0000000028915171 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 1034 Comm: khungtaskd Not tainted 4.19.56 #28
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+0x172/0x1f0 lib/dump_stack.c:113
nmi_cpu_backtrace.cold+0x63/0xa4 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1b0/0x1f8 lib/nmi_backtrace.c:62
arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
watchdog+0x9df/0xee0 kernel/hung_task.c:287
kthread+0x354/0x420 kernel/kthread.c:246
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 3594 Comm: udevd Not tainted 4.19.56 #28
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
RIP: 0010:lockdep_hardirqs_off+0x37/0x2d0 kernel/locking/lockdep.c:2890
Code: 00 00 fc ff df 48 89 c1 48 89 e5 41 55 83 e0 07 48 c1 e9 03 41 54 83
c0 03 49 89 fc 53 0f b6 14 11 65 48 8b 1c 25 40 ee 01 00 <38> d0 7c 08 84
d2 0f 85 10 02 00 00 8b 3d b7 29 5e 07 85 ff 0f 84
RSP: 0018:ffff8880970dfb38 EFLAGS: 00000006
RAX: 0000000000000003 RBX: ffff8880970d4700 RCX: 1ffffffff1161530
RDX: 0000000000000004 RSI: ffffffff81704779 RDI: ffffffff815cd547
RBP: ffff8880970dfb50 R08: ffff8880970d4700 R09: ffffffff89781048
R10: ffffed1012cf4300 R11: 0000000000000001 R12: ffffffff815cd547
R13: ffffffff81afa4b4 R14: ffffffff815cd547 R15: dffffc0000000000
FS: 00007f89098977a0(0000) GS:ffff8880ae900000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffffff600400 CR3: 00000000967bc000 CR4: 00000000001406e0
Call Trace:
trace_hardirqs_off+0x62/0x220 kernel/trace/trace_preemptirq.c:43
seqcount_lockdep_reader_access include/linux/seqlock.h:80 [inline]
read_seqcount_begin include/linux/seqlock.h:164 [inline]
ktime_get_ts64+0xb7/0x3f0 kernel/time/timekeeping.c:889
select_estimate_accuracy+0xd4/0x330 fs/select.c:87
ep_poll+0x478/0xd10 fs/eventpoll.c:1758
do_epoll_wait+0x1b3/0x200 fs/eventpoll.c:2198
__do_sys_epoll_wait fs/eventpoll.c:2208 [inline]
__se_sys_epoll_wait fs/eventpoll.c:2205 [inline]
__x64_sys_epoll_wait+0x97/0xf0 fs/eventpoll.c:2205
do_syscall_64+0xfd/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f8908fab943
Code: 00 31 d2 48 29 c2 64 89 11 48 83 c8 ff eb ea 90 90 90 90 90 90 90 90
83 3d b5 dc 2a 00 00 75 13 49 89 ca b8 e8 00 00 00 0f 05 <48> 3d 01 f0 ff
ff 73 34 c3 48 83 ec 08 e8 3b c4 00 00 48 89 04 24
RSP: 002b:00007ffd1244bc98 EFLAGS: 00000246 ORIG_RAX: 00000000000000e8
RAX: ffffffffffffffda RBX: 0000000000000bb8 RCX: 00007f8908fab943
RDX: 0000000000000008 RSI: 00007ffd1244bd90 RDI: 000000000000000a
RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000bb8 R11: 0000000000000246 R12: 0000000000000003
R13: 0000000000000000 R14: 00000000006ad9a0 R15: 0000000000696030


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

syzbot has found a reproducer for the following crash on:

HEAD commit: aec3002d Linux 4.19.56
git tree: linux-4.19.y

console output: https://syzkaller.appspot.com/x/log.txt?x=14c15a99a00000

kernel config: https://syzkaller.appspot.com/x/.config?x=48b721ea0070d1cd
dashboard link: https://syzkaller.appspot.com/bug?extid=b8dab3b2459def923263
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=13a8ee83a00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=12bb09a3a00000

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

audit: type=1400 audit(1562047191.513:36): avc: denied { map } for
pid=7755 comm="syz-executor084" path="/root/syz-executor084409957"
dev="sda1" ino=1426 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023
tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file permissive=1

block nbd0: shutting down sockets

INFO: task syz-executor084:7757 blocked for more than 140 seconds.

Not tainted 4.19.56 #28
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

syz-executor084 D28928 7757 7753 0x00000004

Call Trace:
context_switch kernel/sched/core.c:2826 [inline]
__schedule+0x80d/0x1c70 kernel/sched/core.c:3474
schedule+0x92/0x1c0 kernel/sched/core.c:3518
schedule_timeout+0x8c8/0xfc0 kernel/time/timer.c:1780
io_schedule_timeout+0x26/0x80 kernel/sched/core.c:5129
do_wait_for_common kernel/sched/completion.c:83 [inline]
__wait_for_common kernel/sched/completion.c:104 [inline]
wait_for_common_io kernel/sched/completion.c:121 [inline]
wait_for_completion_io+0x29c/0x440 kernel/sched/completion.c:169
submit_bio_wait+0x11d/0x1c0 block/bio.c:931
blkdev_issue_flush+0x20b/0x300 block/blk-flush.c:553
blkdev_fsync+0x95/0xd0 fs/block_dev.c:647
vfs_fsync_range+0x141/0x230 fs/sync.c:197
vfs_fsync fs/sync.c:211 [inline]
do_fsync+0x54/0xa0 fs/sync.c:221
__do_sys_fdatasync fs/sync.c:234 [inline]
__se_sys_fdatasync fs/sync.c:232 [inline]
__x64_sys_fdatasync+0x36/0x50 fs/sync.c:232
do_syscall_64+0xfd/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe

RIP: 0033:0x449789
Code: Bad RIP value.
RSP: 002b:00007fba8e1fcce8 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
RAX: ffffffffffffffda RBX: 00000000006dac58 RCX: 0000000000449789
RDX: 0000000000449789 RSI: 0000000000000000 RDI: 0000000000000009
RBP: 00000000006dac50 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000006dac5c
R13: 00007ffc01d74a5f R14: 00007fba8e1fd9c0 R15: 20c49ba5e353f7cf

Showing all locks held in the system:

1 lock held by khungtaskd/1029:
#0: 00000000eca0e8c4 (rcu_read_lock){....}, at:
debug_show_all_locks+0x5f/0x27e kernel/locking/lockdep.c:4435
1 lock held by rsyslogd/7604:
2 locks held by getty/7727:
#0: 00000000f0204946 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 0000000015efb458 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7728:
#0: 00000000cb5b1147 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 00000000560cdf4e (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7729:
#0: 000000007bddcd1c (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 000000001997f524 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7730:
#0: 0000000030ce0a67 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 00000000cf60cb1e (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7731:
#0: 000000007a208e32 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 0000000016a3b44d (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7732:
#0: 00000000540a4f7b (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 000000009493c284 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154
2 locks held by getty/7733:
#0: 0000000098989f02 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:363
#1: 00000000a7619b96 (&ldata->atomic_read_lock){+.+.}, at:

n_tty_read+0x232/0x1b30 drivers/tty/n_tty.c:2154

=============================================

NMI backtrace for cpu 0

CPU: 0 PID: 1029 Comm: khungtaskd Not tainted 4.19.56 #28

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+0x172/0x1f0 lib/dump_stack.c:113
nmi_cpu_backtrace.cold+0x63/0xa4 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1b0/0x1f8 lib/nmi_backtrace.c:62
arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
watchdog+0x9df/0xee0 kernel/hung_task.c:287
kthread+0x354/0x420 kernel/kthread.c:246
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 0 to CPUs 1:

NMI backtrace for cpu 1 skipped: idling at native_safe_halt+0xe/0x10
arch/x86/include/asm/irqflags.h:60

[syzbot]

syzbot suspects this bug was fixed by commit:

commit 76cf93f04c3dedc29660fed2c26fdbc21f604725
Author: Wang Shenran <shenr...@gmail.com>
Date: Wed Jul 24 08:01:10 2019 +0000

hwmon: (acpi_power_meter) Change log level for 'unsafe software power
cap'

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=173fb97ae00000
start commit: aec3002d Linux 4.19.56
git tree: linux-4.19.y

kernel config: https://syzkaller.appspot.com/x/.config?x=48b721ea0070d1cd
dashboard link: https://syzkaller.appspot.com/bug?extid=b8dab3b2459def923263

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=13a8ee83a00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=12bb09a3a00000

If the result looks correct, please mark the bug fixed by replying with:

#syz fix: hwmon: (acpi_power_meter) Change log level for 'unsafe software
power cap'

For information about bisection process see: https://goo.gl/tpsmEJ#bisection