INFO: task hung in fuse_flush

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: 4ba8e26127c3 Linux 4.14.262
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=135b4b38700000
kernel config: https://syzkaller.appspot.com/x/.config?x=51e11aabddb4cf62
dashboard link: https://syzkaller.appspot.com/bug?extid=056d9cd0b9206bdc2302
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)

Unfortunately, I don't have any reproducer for this issue yet.

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

Bluetooth: hci2 command 0x0406 tx timeout
Bluetooth: hci1 command 0x0406 tx timeout
Bluetooth: hci3 command 0x0406 tx timeout
Bluetooth: hci4 command 0x0406 tx timeout
Bluetooth: hci0 command 0x0406 tx timeout
INFO: task syz-executor.0:12455 blocked for more than 140 seconds.
Not tainted 4.14.262-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.0 D28912 12455 8020 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2811 [inline]
__schedule+0x88b/0x1de0 kernel/sched/core.c:3387
schedule+0x8d/0x1b0 kernel/sched/core.c:3431
__rwsem_down_write_failed_common kernel/locking/rwsem-xadd.c:588 [inline]
rwsem_down_write_failed+0x343/0x6d0 kernel/locking/rwsem-xadd.c:617
call_rwsem_down_write_failed+0x13/0x20 arch/x86/lib/rwsem.S:105
__down_write arch/x86/include/asm/rwsem.h:126 [inline]
down_write+0x4f/0x90 kernel/locking/rwsem.c:56
inode_lock include/linux/fs.h:719 [inline]
fuse_flush+0x1a1/0x4e0 fs/fuse/file.c:420
filp_close+0x9d/0x140 fs/open.c:1158
__close_fd+0x151/0x230 fs/file.c:639
SYSC_close fs/open.c:1177 [inline]
SyS_close+0x42/0x90 fs/open.c:1175
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x7f6002078c9b
RSP: 002b:00007fff249ede10 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 00007f6002078c9b
RDX: 0000001b30c20000 RSI: 0000001b30c25ab4 RDI: 0000000000000004
RBP: 00007f60021da960 R08: 0000000000000000 R09: 00000000e0f0a99d
R10: 0008507e708dc811 R11: 0000000000000293 R12: 000000000003f4cd
R13: 00007fff249edf10 R14: 00007f60021d9030 R15: 0000000000000032
INFO: task syz-executor.0:12460 blocked for more than 140 seconds.
Not tainted 4.14.262-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.0 D27768 12460 8020 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2811 [inline]
__schedule+0x88b/0x1de0 kernel/sched/core.c:3387
schedule+0x8d/0x1b0 kernel/sched/core.c:3431
fuse_wait_on_page_writeback fs/fuse/file.c:382 [inline]
fuse_wait_on_page_writeback.isra.0+0xdc/0x120 fs/fuse/file.c:378
fuse_launder_page fs/fuse/file.c:2032 [inline]
fuse_launder_page+0xa2/0xd0 fs/fuse/file.c:2025
do_launder_page mm/truncate.c:609 [inline]
invalidate_inode_pages2_range+0x547/0xc00 mm/truncate.c:685
fuse_finish_open+0x262/0x500 fs/fuse/file.c:181
fuse_open_common+0x1fc/0x250 fs/fuse/file.c:221
do_dentry_open+0x44b/0xec0 fs/open.c:777
vfs_open+0x105/0x220 fs/open.c:888
do_last fs/namei.c:3428 [inline]
path_openat+0x628/0x2970 fs/namei.c:3569
do_filp_open+0x179/0x3c0 fs/namei.c:3603
do_sys_open+0x296/0x410 fs/open.c:1081
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x7f60020c6059
RSP: 002b:00007f6000a3b168 EFLAGS: 00000246 ORIG_RAX: 0000000000000055
RAX: ffffffffffffffda RBX: 00007f60021d8f60 RCX: 00007f60020c6059
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000020000000
RBP: 00007f600212008d R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007fff249eddaf R14: 00007f6000a3b300 R15: 0000000000022000

Showing all locks held in the system:
1 lock held by khungtaskd/1534:
#0: (tasklist_lock){.+.+}, at: [<ffffffff8701f0b7>] debug_show_all_locks+0x7c/0x21a kernel/locking/lockdep.c:4548
1 lock held by in:imklog/7719:
#0: (&f->f_pos_lock){+.+.}, at: [<ffffffff818d58ab>] __fdget_pos+0x1fb/0x2b0 fs/file.c:778
1 lock held by syz-executor.0/12455:
#0: (&sb->s_type->i_mutex_key#21){+.+.}, at: [<ffffffff822f0e21>] inode_lock include/linux/fs.h:719 [inline]
#0: (&sb->s_type->i_mutex_key#21){+.+.}, at: [<ffffffff822f0e21>] fuse_flush+0x1a1/0x4e0 fs/fuse/file.c:420
2 locks held by syz-executor.0/12460:
#0: (sb_writers#13){.+.+}, at: [<ffffffff818de91a>] sb_start_write include/linux/fs.h:1551 [inline]
#0: (sb_writers#13){.+.+}, at: [<ffffffff818de91a>] mnt_want_write+0x3a/0xb0 fs/namespace.c:386
#1: (&sb->s_type->i_mutex_key#21){+.+.}, at: [<ffffffff822f0a67>] inode_lock include/linux/fs.h:719 [inline]
#1: (&sb->s_type->i_mutex_key#21){+.+.}, at: [<ffffffff822f0a67>] fuse_open_common+0x177/0x250 fs/fuse/file.c:214

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

NMI backtrace for cpu 1
CPU: 1 PID: 1534 Comm: khungtaskd Not tainted 4.14.262-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x1b2/0x281 lib/dump_stack.c:58
nmi_cpu_backtrace.cold+0x57/0x93 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x13a/0x180 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:140 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:195 [inline]
watchdog+0x5b9/0xb40 kernel/hung_task.c:274
kthread+0x30d/0x420 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 8 Comm: rcu_preempt Not tainted 4.14.262-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
task: ffff8880b5420200 task.stack: ffff8880b5428000
RIP: 0010:trace_hardirqs_off_caller+0xc5/0x2b0 kernel/locking/lockdep.c:2957
RSP: 0018:ffff8880b542fb08 EFLAGS: 00000097
RAX: 0000000000000003 RBX: ffff8880b5420200 RCX: 1ffffffff17d93a8
RDX: 0000000000000004 RSI: 0000000000000000 RDI: ffff8880b5420a84
RBP: ffffffff8723fac6 R08: ffffffff8bfe2308 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff8880b5420200
R13: ffff8880b542fbd8 R14: ffff8880b542fd18 R15: 1ffff11016a85f6b
FS: 0000000000000000(0000) GS:ffff8880ba400000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f43e3991000 CR3: 00000000a231f000 CR4: 00000000003406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
_raw_spin_lock_irqsave+0x66/0xc0 kernel/locking/spinlock.c:160
debug_object_assert_init lib/debugobjects.c:638 [inline]
debug_object_assert_init+0xdd/0x2d0 lib/debugobjects.c:627
debug_timer_assert_init kernel/time/timer.c:708 [inline]
debug_assert_init kernel/time/timer.c:756 [inline]
try_to_del_timer_sync+0x5d/0xe0 kernel/time/timer.c:1176
del_timer_sync+0x17c/0x240 kernel/time/timer.c:1246
schedule_timeout+0x4b7/0xe90 kernel/time/timer.c:1748
rcu_gp_kthread+0xc0a/0x1e60 kernel/rcu/tree.c:2255
kthread+0x30d/0x420 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
Code: 40 9d ec 8b 48 ba 00 00 00 00 00 fc ff df 48 89 c1 83 e0 07 48 c1 e9 03 83 c0 03 0f b6 14 11 38 d0 7c 08 84 d2 0f 85 76 01 00 00 <8b> 0d f5 97 ab 0a 85 c9 75 3d 48 c7 c0 c0 93 f0 88 48 ba 00 00
----------------
Code disassembly (best guess), 4 bytes skipped:
0: 48 ba 00 00 00 00 00 movabs $0xdffffc0000000000,%rdx
7: fc ff df
a: 48 89 c1 mov %rax,%rcx
d: 83 e0 07 and $0x7,%eax
10: 48 c1 e9 03 shr $0x3,%rcx
14: 83 c0 03 add $0x3,%eax
17: 0f b6 14 11 movzbl (%rcx,%rdx,1),%edx
1b: 38 d0 cmp %dl,%al
1d: 7c 08 jl 0x27
1f: 84 d2 test %dl,%dl
21: 0f 85 76 01 00 00 jne 0x19d
* 27: 8b 0d f5 97 ab 0a mov 0xaab97f5(%rip),%ecx # 0xaab9822 <-- trapping instruction
2d: 85 c9 test %ecx,%ecx
2f: 75 3d jne 0x6e
31: 48 c7 c0 c0 93 f0 88 mov $0xffffffff88f093c0,%rax
38: 48 rex.W
39: ba .byte 0xba


---
This report 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 issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

[syzbot]

syzbot has found a reproducer for the following issue on:

HEAD commit: 84bae26850e3 Linux 4.14.284
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=173e9837f00000
kernel config: https://syzkaller.appspot.com/x/.config?x=3f2be884e0c5d592

dashboard link: https://syzkaller.appspot.com/bug?extid=056d9cd0b9206bdc2302
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=105f3f1bf00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=115aa08ff00000

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

IPVS: ftp: loaded support on port[0] = 21
INFO: task syz-executor178:8016 blocked for more than 140 seconds.
Not tainted 4.14.284-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

syz-executor178 D28912 8016 7992 0x00000004

Call Trace:
context_switch kernel/sched/core.c:2811 [inline]
__schedule+0x88b/0x1de0 kernel/sched/core.c:3387
schedule+0x8d/0x1b0 kernel/sched/core.c:3431
__rwsem_down_write_failed_common kernel/locking/rwsem-xadd.c:588 [inline]
rwsem_down_write_failed+0x343/0x6d0 kernel/locking/rwsem-xadd.c:617
call_rwsem_down_write_failed+0x13/0x20 arch/x86/lib/rwsem.S:105
__down_write arch/x86/include/asm/rwsem.h:126 [inline]
down_write+0x4f/0x90 kernel/locking/rwsem.c:56
inode_lock include/linux/fs.h:719 [inline]

fuse_flush+0x1c7/0x520 fs/fuse/file.c:423

filp_close+0x9d/0x140 fs/open.c:1158
__close_fd+0x151/0x230 fs/file.c:639
SYSC_close fs/open.c:1177 [inline]
SyS_close+0x42/0x90 fs/open.c:1175
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x46/0xbb

RIP: 0033:0x7f9499f53a4b
RSP: 002b:00007ffd91fdfb90 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: ffffffffffffffda RBX: 0000000000000006 RCX: 00007f9499f53a4b
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000005
RBP: 0000000000091eca R08: 0000000000000000 R09: 0000000000000008
R10: 0000000000000000 R11: 0000000000000293 R12: 00007f949a0244dc
R13: 00007ffd91fdfbf0 R14: 0000000000000032 R15: 00007f949a0244c0
INFO: task syz-executor178:8017 blocked for more than 140 seconds.
Not tainted 4.14.284-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

syz-executor178 D28464 8017 7992 0x00000004

Call Trace:
context_switch kernel/sched/core.c:2811 [inline]
__schedule+0x88b/0x1de0 kernel/sched/core.c:3387
schedule+0x8d/0x1b0 kernel/sched/core.c:3431

fuse_wait_on_page_writeback fs/fuse/file.c:385 [inline]
fuse_wait_on_page_writeback.isra.0+0xdc/0x120 fs/fuse/file.c:381
fuse_launder_page fs/fuse/file.c:2042 [inline]
fuse_launder_page+0xa2/0xd0 fs/fuse/file.c:2035

do_launder_page mm/truncate.c:609 [inline]
invalidate_inode_pages2_range+0x547/0xc00 mm/truncate.c:685
fuse_finish_open+0x262/0x500 fs/fuse/file.c:181

fuse_open_common+0x234/0x290 fs/fuse/file.c:224

do_dentry_open+0x44b/0xec0 fs/open.c:777
vfs_open+0x105/0x220 fs/open.c:888
do_last fs/namei.c:3428 [inline]
path_openat+0x628/0x2970 fs/namei.c:3569
do_filp_open+0x179/0x3c0 fs/namei.c:3603
do_sys_open+0x296/0x410 fs/open.c:1081
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x46/0xbb

RIP: 0033:0x7f9499f931c9
RSP: 002b:00007f9499f432f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 00007f949a0244c0 RCX: 00007f9499f931c9
RDX: 0000000000000000 RSI: 0000000000000600 RDI: 0000000020000100
RBP: 00007f9499ff13ac R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0030656c69662f2e
R13: 00007f9499fed3a0 R14: 00007f9499fef3a8 R15: 00007f949a0244c8

Showing all locks held in the system:

1 lock held by khungtaskd/1533:
#0: (tasklist_lock){.+.+}, at: [<ffffffff87028029>] debug_show_all_locks+0x7c/0x21a kernel/locking/lockdep.c:4548
1 lock held by syz-executor178/8016:
#0: (&sb->s_type->i_mutex_key#18){+.+.}, at: [<ffffffff822f41f7>] inode_lock include/linux/fs.h:719 [inline]
#0: (&sb->s_type->i_mutex_key#18){+.+.}, at: [<ffffffff822f41f7>] fuse_flush+0x1c7/0x520 fs/fuse/file.c:423
2 locks held by syz-executor178/8017:
#0: (sb_writers#10){.+.+}, at: [<ffffffff818e04ca>] sb_start_write include/linux/fs.h:1551 [inline]
#0: (sb_writers#10){.+.+}, at: [<ffffffff818e04ca>] mnt_want_write+0x3a/0xb0 fs/namespace.c:386
#1: (&sb->s_type->i_mutex_key#18){+.+.}, at: [<ffffffff822f3e04>] inode_lock include/linux/fs.h:719 [inline]
#1: (&sb->s_type->i_mutex_key#18){+.+.}, at: [<ffffffff822f3e04>] fuse_open_common+0x1a4/0x290 fs/fuse/file.c:217

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

NMI backtrace for cpu 0
CPU: 0 PID: 1533 Comm: khungtaskd Not tainted 4.14.284-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x1b2/0x281 lib/dump_stack.c:58
nmi_cpu_backtrace.cold+0x57/0x93 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x13a/0x180 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:140 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:195 [inline]
watchdog+0x5b9/0xb40 kernel/hung_task.c:274
kthread+0x30d/0x420 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1 skipped: idling at pc 0xffffffff872480fe