INFO: task hung in do_truncate

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit: 716a685fdb89 Merge branch 'x86-hyperv-for-linus' of git://..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=11626def800000
kernel config: https://syzkaller.appspot.com/x/.config?x=4f65cd4286737868
dashboard link: https://syzkaller.appspot.com/bug?extid=8860bc3998372a09885a
compiler: gcc (GCC) 8.0.1 20180413 (experimental)
CC: [linux-...@vger.kernel.org linux-...@vger.kernel.org
vi...@zeniv.linux.org.uk]

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+8860bc...@syzkaller.appspotmail.com

device loop0 blocksize: 4096
__find_get_block_slow() failed. block=1, b_blocknr=8
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
INFO: task syz-executor0:14830 blocked for more than 120 seconds.
b_state=0x00000029, b_size=512
Not tainted 4.17.0+ #84
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor0 D
device loop0 blocksize: 4096
23392 14830 7234 0x00000004
Call Trace:
__find_get_block_slow() failed. block=2, b_blocknr=16
context_switch kernel/sched/core.c:2856 [inline]
__schedule+0x801/0x1e30 kernel/sched/core.c:3498
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
schedule+0xef/0x430 kernel/sched/core.c:3542
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__rwsem_down_write_failed_common+0x919/0x15d0
kernel/locking/rwsem-xadd.c:566
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=1, b_blocknr=8
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=1, b_blocknr=8
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
rwsem_down_write_failed+0xe/0x10 kernel/locking/rwsem-xadd.c:595
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
call_rwsem_down_write_failed+0x17/0x30 arch/x86/lib/rwsem.S:117
__down_write arch/x86/include/asm/rwsem.h:142 [inline]
down_write+0xa2/0x120 kernel/locking/rwsem.c:72
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
inode_lock include/linux/fs.h:713 [inline]
do_truncate+0x197/0x2a0 fs/open.c:61
__find_get_block_slow() failed. block=1, b_blocknr=8
handle_truncate fs/namei.c:2960 [inline]
do_last fs/namei.c:3379 [inline]
path_openat+0x3195/0x4dc0 fs/namei.c:3511
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=1, b_blocknr=8
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=1, b_blocknr=8
do_filp_open+0x249/0x350 fs/namei.c:3545
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
do_sys_open+0x56f/0x740 fs/open.c:1101
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=1, b_blocknr=8
ksys_open include/linux/syscalls.h:1268 [inline]
__do_sys_creat fs/open.c:1159 [inline]
__se_sys_creat fs/open.c:1157 [inline]
__x64_sys_creat+0x61/0x80 fs/open.c:1157
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287
__find_get_block_slow() failed. block=2, b_blocknr=16
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=1, b_blocknr=8
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455a09
b_state=0x00000029, b_size=512
Code: Bad RIP value.
device loop0 blocksize: 4096
RSP: 002b:00007f62ed6dbc68 EFLAGS: 00000246 ORIG_RAX: 0000000000000055
RAX: ffffffffffffffda RBX: 00007f62ed6dc6d4 RCX: 0000000000455a09
__find_get_block_slow() failed. block=2, b_blocknr=16
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000020000180
RBP: 000000000072bf50 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
R13: 000000000000006a R14: 00000000006f5a90 R15: 0000000000000001

Showing all locks held in the system:
__find_get_block_slow() failed. block=2, b_blocknr=16
3 locks held by kworker/u4:4/524:
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
2 locks held by khungtaskd/895:
#0: 0000000029733b38
__find_get_block_slow() failed. block=1, b_blocknr=8
(rcu_read_lock){....}
b_state=0x00000029, b_size=512
, at: check_hung_uninterruptible_tasks kernel/hung_task.c:175 [inline]
, at: watchdog+0x1ff/0xf60 kernel/hung_task.c:249
#1: 0000000029733b38
device loop0 blocksize: 4096
(rcu_read_lock){....}, at: debug_show_all_locks+0xc8/0x40c
kernel/locking/lockdep.c:4461
__find_get_block_slow() failed. block=2, b_blocknr=16
1 lock held by rsyslogd/4376:
#0:
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
0000000010666d00 (&f->f_pos_lock){+.+.}
__find_get_block_slow() failed. block=1, b_blocknr=8
, at: __fdget_pos+0x1a9/0x1e0 fs/file.c:766
2 locks held by getty/4466:
b_state=0x00000029, b_size=512
#0: 000000006fd10e9e (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1:
device loop0 blocksize: 4096
000000008a018599 (&ldata->atomic_read_lock){+.+.}
__find_get_block_slow() failed. block=2, b_blocknr=16
, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4467:
b_state=0x00000029, b_size=512
#0: 0000000054f89a73 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1:
device loop0 blocksize: 4096
00000000fcc5757c (&ldata->atomic_read_lock){+.+.}
__find_get_block_slow() failed. block=1, b_blocknr=8
, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4468:
b_state=0x00000029, b_size=512
#0: 000000003d7e2c16 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1:
device loop0 blocksize: 4096
000000005026f3cc (&ldata->atomic_read_lock
__find_get_block_slow() failed. block=2, b_blocknr=16
){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4469:
b_state=0x00000029, b_size=512
#0: 00000000819a77c5 (&tty->ldisc_sem){++++}, at:
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1:
device loop0 blocksize: 4096
0000000051afc314 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
__find_get_block_slow() failed. block=1, b_blocknr=8
2 locks held by getty/4470:
#0:
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
0000000064d268a5 (&tty->ldisc_sem){++++}
__find_get_block_slow() failed. block=2, b_blocknr=16
, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1:
b_state=0x00000029, b_size=512
000000003f596769 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4471:
device loop0 blocksize: 4096
#0: 00000000a7a647cb (&tty->ldisc_sem
__find_get_block_slow() failed. block=1, b_blocknr=8
){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1:
b_state=0x00000029, b_size=512
000000004541cfe3 (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4472:
device loop0 blocksize: 4096
#0: 00000000b2fbbdef
__find_get_block_slow() failed. block=2, b_blocknr=16
(&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40
drivers/tty/tty_ldsem.c:365
b_state=0x00000029, b_size=512
#1: 00000000f044058d (&ldata->atomic_read_lock){+.+.}, at:
n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
8 locks held by syz-executor0/14784:
device loop0 blocksize: 4096
2 locks held by syz-executor0/14830:
#0: 0000000021d78d9c (sb_writers#17){.+.+}
__find_get_block_slow() failed. block=1, b_blocknr=8
, at: sb_start_write include/linux/fs.h:1550 [inline]
, at: mnt_want_write+0x3f/0xc0 fs/namespace.c:386
#1:
b_state=0x00000029, b_size=512
000000007a5756f6 (&sb->s_type->i_mutex_key#18){++++}, at: inode_lock
include/linux/fs.h:713 [inline]
000000007a5756f6 (&sb->s_type->i_mutex_key#18){++++}, at:
do_truncate+0x197/0x2a0 fs/open.c:61
1 lock held by syz-executor0/14837:
device loop0 blocksize: 4096
#0: 0000000053abcc40 (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x1a9/0x1e0
fs/file.c:766

__find_get_block_slow() failed. block=2, b_blocknr=16
=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 895 Comm: khungtaskd Not tainted 4.17.0+ #84
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
b_state=0x00000029, b_size=512
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1b9/0x294 lib/dump_stack.c:113
device loop0 blocksize: 4096
nmi_cpu_backtrace.cold.4+0x19/0xce lib/nmi_backtrace.c:103
nmi_trigger_cpumask_backtrace+0x151/0x192 lib/nmi_backtrace.c:62
__find_get_block_slow() failed. block=1, b_blocknr=8
arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
trigger_all_cpu_backtrace include/linux/nmi.h:138 [inline]
check_hung_task kernel/hung_task.c:132 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:190 [inline]
watchdog+0xc10/0xf60 kernel/hung_task.c:249
b_state=0x00000029, b_size=512
device loop0 blocksize: 4096
__find_get_block_slow() failed. block=2, b_blocknr=16
kthread+0x345/0x410 kernel/kthread.c:240
b_state=0x00000029, b_size=512
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
Sending NMI from CPU 0 to CPUs 1:
device loop0 blocksize: 4096
NMI backtrace for cpu 1
CPU: 1 PID: 14784 Comm: syz-executor0 Not tainted 4.17.0+ #84
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
RIP: 0010:variable_test_bit arch/x86/include/asm/bitops.h:335 [inline]
RIP: 0010:cpumask_test_cpu include/linux/cpumask.h:332 [inline]
RIP: 0010:trace_lock_release include/trace/events/lock.h:58 [inline]
RIP: 0010:lock_release+0x19c/0xa10 kernel/locking/lockdep.c:3942
Code: 08 84 d2 0f 85 43 06 00 00 41 c7 87 34 08 00 00 01 00 00 00 0f 1f 44
00 00 65 8b 05 be 62 a4 7e 89 c0 48 0f a3 05 e4 d0 1e 08 <0f> 82 1c 05 00
00 4d 8d bc 24 40 ff ff ff 48 c7 c7 00 e8 09 89 48
RSP: 0018:ffff8801daf078a8 EFLAGS: 00000047
RAX: 0000000000000001 RBX: 1ffff1003b5e0f1a RCX: ffff88018265aeb8
RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff88018265aeb4
RBP: ffff8801daf079d8 R08: 0000000000000000 R09: ffff8801c71cdd00
R10: ffff8801c71cde48 R11: 1ffff1003b5e0edf R12: ffff8801daf079b0
R13: ffff8801daf2c718 R14: ffff8801daf07ab8 R15: ffff88018265a680
FS: 00007f62ed6fd700(0000) GS:ffff8801daf00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000cc0000 CR3: 00000001c23e6000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<IRQ>
__raw_spin_unlock include/linux/spinlock_api_smp.h:150 [inline]
_raw_spin_unlock+0x1a/0x30 kernel/locking/spinlock.c:176
rq_unlock kernel/sched/sched.h:1838 [inline]
scheduler_tick+0x1d4/0x420 kernel/sched/core.c:3085
update_process_times+0x51/0x70 kernel/time/timer.c:1641
tick_sched_handle+0x9f/0x180 kernel/time/tick-sched.c:164
tick_sched_timer+0x45/0x130 kernel/time/tick-sched.c:1274
__run_hrtimer kernel/time/hrtimer.c:1398 [inline]
__hrtimer_run_queues+0x3e3/0x10a0 kernel/time/hrtimer.c:1460
hrtimer_interrupt+0x2f3/0x750 kernel/time/hrtimer.c:1518
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1025 [inline]
smp_apic_timer_interrupt+0x15d/0x710 arch/x86/kernel/apic/apic.c:1050
apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:863
</IRQ>
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783
[inline]
RIP: 0010:console_trylock_spinning kernel/printk/printk.c:1678 [inline]
RIP: 0010:vprintk_emit+0xbd0/0xdd0 kernel/printk/printk.c:1906
Code: fc ff df 41 80 3c 04 00 0f 85 08 02 00 00 48 83 3d fc c8 70 07 00 0f
84 f7 00 00 00 e8 c9 70 18 00 48 8b bd a8 fe ff ff 57 9d <0f> 1f 44 00 00
e9 18 fe ff ff 41 80 fd 64 0f 84 eb f9 ff ff e9 ef
RSP: 0018:ffff8801854ce810 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
RAX: 0000000000040000 RBX: 0000000000000200 RCX: ffffc900120ca000
RDX: 0000000000040000 RSI: ffffffff8160e037 RDI: 0000000000000246
RBP: ffff8801854ce9a0 R08: ffff88018265aeb8 R09: 0000000000000006
R10: ffff88018265a680 R11: 0000000000000000 R12: 1ffffffff11a3525
R13: 000000000000001c R14: ffffed0030a99d1f R15: ffffffff8a6d3420
vprintk_default+0x28/0x30 kernel/printk/printk.c:1947
vprintk_func+0x7a/0xe7 kernel/printk/printk_safe.c:379
printk+0x9e/0xba kernel/printk/printk.c:1980
__find_get_block_slow fs/buffer.c:237 [inline]
__find_get_block.cold.58+0xdd/0x103 fs/buffer.c:1287
__getblk_slow fs/buffer.c:1032 [inline]
__getblk_gfp+0x2a1/0xaf0 fs/buffer.c:1313
__bread_gfp+0x2d/0x310 fs/buffer.c:1347
sb_bread include/linux/buffer_head.h:309 [inline]
fat_ent_bread+0x173/0x290 fs/fat/fatent.c:106
fat_ent_read_block fs/fat/fatent.c:441 [inline]
fat_alloc_clusters+0x8bf/0x16b0 fs/fat/fatent.c:489
fat_add_cluster+0x72/0x140 fs/fat/inode.c:101
__fat_get_block fs/fat/inode.c:148 [inline]
fat_get_block+0x373/0xaf0 fs/fat/inode.c:177
__block_write_begin_int+0x505/0x1ad0 fs/buffer.c:1958
__block_write_begin fs/buffer.c:2008 [inline]
block_write_begin+0xd2/0x350 fs/buffer.c:2067
cont_write_begin+0x531/0x820 fs/buffer.c:2417
fat_write_begin+0x8d/0x120 fs/fat/inode.c:223
generic_perform_write+0x39a/0x6a0 mm/filemap.c:3139
__generic_file_write_iter+0x26e/0x630 mm/filemap.c:3264
generic_file_write_iter+0x430/0x850 mm/filemap.c:3292
call_write_iter include/linux/fs.h:1786 [inline]
new_sync_write fs/read_write.c:474 [inline]
__vfs_write+0x64d/0x960 fs/read_write.c:487
vfs_write+0x1f8/0x560 fs/read_write.c:549
ksys_write+0xf9/0x250 fs/read_write.c:598
__do_sys_write fs/read_write.c:610 [inline]
__se_sys_write fs/read_write.c:607 [inline]
__x64_sys_write+0x73/0xb0 fs/read_write.c:607
do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455a09
Code: 1d ba fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48 89 f7
48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff
ff 0f 83 eb b9 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f62ed6fcc68 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 00007f62ed6fd6d4 RCX: 0000000000455a09
RDX: 00000000fffffd97 RSI: 0000000020000180 RDI: 0000000000000013
RBP: 000000000072bea0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000000007ab R14: 00000000007008a8 R15: 0000000000000000


---
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#bug-status-tracking for how to communicate with
syzbot.