INFO: task hung in vfs_unlink

From: syzbot
Date: Wed Oct 23 2019 - 03:25:11 EST

Next message: Jason Wang: "Re: [PATCH v2] vhost: introduce mdev based hardware backend"
Previous message: syzbot: "INFO: task hung in register_netdevice_notifier (2)"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello,

syzbot found the following crash on:

HEAD commit: d72e90f3 Linux 4.18-rc6
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=104dc658400000
kernel config: https://syzkaller.appspot.com/x/.config?x=68af3495408deac5
dashboard link: https://syzkaller.appspot.com/bug?extid=36feff43582f1f97716a
compiler: gcc (GCC) 8.0.1 20180413 (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+36feff43582f1f97716a@xxxxxxxxxxxxxxxxxxxxxxxxx

binder: 12679:12746 ioctl 40046207 0 returned -16
binder: 12679:12746 unknown command -565157109
binder: 12679:12746 ioctl c0306201 204edfd0 returned -22
binder: 12679:12743 unknown command 0
binder: 12679:12743 ioctl c0306201 20007000 returned -22
INFO: task syz-executor7:12738 blocked for more than 140 seconds.
Not tainted 4.18.0-rc6+ #160
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor7 D25832 12738 4599 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_write_failed_common+0x95d/0x1630 kernel/locking/rwsem-xadd.c:566
rwsem_down_write_failed+0xe/0x10 kernel/locking/rwsem-xadd.c:595
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+0xaa/0x130 kernel/locking/rwsem.c:72
inode_lock include/linux/fs.h:715 [inline]
vfs_unlink+0xd1/0x510 fs/namei.c:4001
do_unlinkat+0x6cc/0xa30 fs/namei.c:4073
__do_sys_unlink fs/namei.c:4120 [inline]
__se_sys_unlink fs/namei.c:4118 [inline]
__x64_sys_unlink+0x42/0x50 fs/namei.c:4118
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455ab9
Code: e0 1f 48 89 04 24 e8 b6 6f fd ff e8 81 6a fd ff e8 5c 68 fd ff 48 8d 05 23 cd 48 00 48 89 04 24 48 c7 44 24 08 1d 00 00 00 e8 <13> 5e fd ff 0f 0b e8 8c 44 00 00 e9 07 f0 ff ff cc cc cc cc cc cc
RSP: 002b:00007f2301e2cc68 EFLAGS: 00000246 ORIG_RAX: 0000000000000057
RAX: ffffffffffffffda RBX: 00007f2301e2d6d4 RCX: 0000000000455ab9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000020000300
RBP: 000000000072bf48 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000004c0088 R14: 00000000004d4350 R15: 0000000000000001
INFO: task syz-executor7:12740 blocked for more than 140 seconds.
Not tainted 4.18.0-rc6+ #160
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor7 D24216 12740 4599 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_write_failed_common+0x95d/0x1630 kernel/locking/rwsem-xadd.c:566
rwsem_down_write_failed+0xe/0x10 kernel/locking/rwsem-xadd.c:595
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+0xaa/0x130 kernel/locking/rwsem.c:72
inode_lock include/linux/fs.h:715 [inline]
lock_mount+0x8c/0x2e0 fs/namespace.c:2088
do_add_mount+0x27/0x370 fs/namespace.c:2465
do_new_mount fs/namespace.c:2532 [inline]
do_mount+0x193f/0x30e0 fs/namespace.c:2848
ksys_mount+0x12d/0x140 fs/namespace.c:3064
__do_sys_mount fs/namespace.c:3078 [inline]
__se_sys_mount fs/namespace.c:3075 [inline]
__x64_sys_mount+0xbe/0x150 fs/namespace.c:3075
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455ab9
Code: e0 1f 48 89 04 24 e8 b6 6f fd ff e8 81 6a fd ff e8 5c 68 fd ff 48 8d 05 23 cd 48 00 48 89 04 24 48 c7 44 24 08 1d 00 00 00 e8 <13> 5e fd ff 0f 0b e8 8c 44 00 00 e9 07 f0 ff ff cc cc cc cc cc cc
RSP: 002b:00007f2301e0bc68 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
RAX: ffffffffffffffda RBX: 00007f2301e0c6d4 RCX: 0000000000455ab9
RDX: 0000000020000900 RSI: 0000000020000000 RDI: 0000000000000000
RBP: 000000000072bff0 R08: 0000000020000380 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000004c0201 R14: 00000000004cfe50 R15: 0000000000000002
INFO: task syz-executor7:12742 blocked for more than 140 seconds.
Not tainted 4.18.0-rc6+ #160
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor7 D25408 12742 4599 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_write_failed_common+0x95d/0x1630 kernel/locking/rwsem-xadd.c:566
rwsem_down_write_failed+0xe/0x10 kernel/locking/rwsem-xadd.c:595
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+0xaa/0x130 kernel/locking/rwsem.c:72
inode_lock include/linux/fs.h:715 [inline]
utimes_common.isra.1+0x45c/0x8e0 fs/utimes.c:90
do_utimes+0x1f7/0x380 fs/utimes.c:156
do_futimesat+0x249/0x350 fs/utimes.c:212
__do_sys_utimes fs/utimes.c:225 [inline]
__se_sys_utimes fs/utimes.c:222 [inline]
__x64_sys_utimes+0x59/0x80 fs/utimes.c:222
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455ab9
Code: e0 1f 48 89 04 24 e8 b6 6f fd ff e8 81 6a fd ff e8 5c 68 fd ff 48 8d 05 23 cd 48 00 48 89 04 24 48 c7 44 24 08 1d 00 00 00 e8 <13> 5e fd ff 0f 0b e8 8c 44 00 00 e9 07 f0 ff ff cc cc cc cc cc cc
RSP: 002b:00007f2301deac68 EFLAGS: 00000246 ORIG_RAX: 00000000000000eb
RAX: ffffffffffffffda RBX: 00007f2301deb6d4 RCX: 0000000000455ab9
RDX: 0000000000000000 RSI: 00000000200002c0 RDI: 00000000200000c0
RBP: 000000000072c098 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000004c2735 R14: 00000000004d4410 R15: 0000000000000003
INFO: task syz-executor7:12744 blocked for more than 140 seconds.
Not tainted 4.18.0-rc6+ #160
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor7 D26504 12744 4599 0x00000004
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_write_failed_common+0x95d/0x1630 kernel/locking/rwsem-xadd.c:566
rwsem_down_write_failed+0xe/0x10 kernel/locking/rwsem-xadd.c:595
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_nested+0xae/0x130 kernel/locking/rwsem.c:194
inode_lock_nested include/linux/fs.h:750 [inline]
do_unlinkat+0x3d8/0xa30 fs/namei.c:4059
__do_sys_unlink fs/namei.c:4120 [inline]
__se_sys_unlink fs/namei.c:4118 [inline]
__x64_sys_unlink+0x42/0x50 fs/namei.c:4118
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455ab9
Code: e0 1f 48 89 04 24 e8 b6 6f fd ff e8 81 6a fd ff e8 5c 68 fd ff 48 8d 05 23 cd 48 00 48 89 04 24 48 c7 44 24 08 1d 00 00 00 e8 <13> 5e fd ff 0f 0b e8 8c 44 00 00 e9 07 f0 ff ff cc cc cc cc cc cc
RSP: 002b:00007f2301dc9c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000057
RAX: ffffffffffffffda RBX: 00007f2301dca6d4 RCX: 0000000000455ab9
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000020000300
RBP: 000000000072c140 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000004c0088 R14: 00000000004d4350 R15: 0000000000000004

Showing all locks held in the system:
1 lock held by khungtaskd/902:
#0: 00000000b4fedee0 (rcu_read_lock){....}, at: debug_show_all_locks+0xd0/0x428 kernel/locking/lockdep.c:4461
1 lock held by rsyslogd/4458:
#0: 00000000cd393d5f (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x1bb/0x200 fs/file.c:766
2 locks held by getty/4548:
#0: 00000000900c6e8e (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1: 000000004ed6f2b2 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4549:
#0: 000000004a7c6f30 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1: 00000000950f14ac (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4550:
#0: 00000000cd10982b (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1: 00000000e9751603 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4551:
#0: 000000000fcf93b3 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1: 00000000fbe330db (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4552:
#0: 00000000604559fd (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1: 00000000736bec6e (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4553:
#0: 00000000bbb8dd50 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1: 0000000051ed7442 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4554:
#0: 00000000f0092d1e (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
#1: 00000000e841c59b (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by syz-executor7/12668:
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: sb_start_write include/linux/fs.h:1554 [inline]
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: mnt_want_write+0x3f/0xc0 fs/namespace.c:386
#1: 000000000ea5b75f (&sb->s_type->i_mutex_key#25){++++}, at: inode_lock include/linux/fs.h:715 [inline]
#1: 000000000ea5b75f (&sb->s_type->i_mutex_key#25){++++}, at: utimes_common.isra.1+0x45c/0x8e0 fs/utimes.c:90
3 locks held by syz-executor7/12738:
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: sb_start_write include/linux/fs.h:1554 [inline]
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: mnt_want_write+0x3f/0xc0 fs/namespace.c:386
#1: 000000005a55d485 (&sb->s_type->i_mutex_key#25/1){+.+.}, at: inode_lock_nested include/linux/fs.h:750 [inline]
#1: 000000005a55d485 (&sb->s_type->i_mutex_key#25/1){+.+.}, at: do_unlinkat+0x3d8/0xa30 fs/namei.c:4059
#2: 000000000ea5b75f (&sb->s_type->i_mutex_key#25){++++}, at: inode_lock include/linux/fs.h:715 [inline]
#2: 000000000ea5b75f (&sb->s_type->i_mutex_key#25){++++}, at: vfs_unlink+0xd1/0x510 fs/namei.c:4001
1 lock held by syz-executor7/12740:
#0: 000000005a55d485 (&sb->s_type->i_mutex_key#25){++++}, at: inode_lock include/linux/fs.h:715 [inline]
#0: 000000005a55d485 (&sb->s_type->i_mutex_key#25){++++}, at: lock_mount+0x8c/0x2e0 fs/namespace.c:2088
2 locks held by syz-executor7/12742:
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: sb_start_write include/linux/fs.h:1554 [inline]
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: mnt_want_write+0x3f/0xc0 fs/namespace.c:386
#1: 000000000ea5b75f (&sb->s_type->i_mutex_key#25){++++}, at: inode_lock include/linux/fs.h:715 [inline]
#1: 000000000ea5b75f (&sb->s_type->i_mutex_key#25){++++}, at: utimes_common.isra.1+0x45c/0x8e0 fs/utimes.c:90
2 locks held by syz-executor7/12744:
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: sb_start_write include/linux/fs.h:1554 [inline]
#0: 00000000b9e8b92c (sb_writers#23){.+.+}, at: mnt_want_write+0x3f/0xc0 fs/namespace.c:386
#1: 000000005a55d485 (&sb->s_type->i_mutex_key#25/1){+.+.}, at: inode_lock_nested include/linux/fs.h:750 [inline]
#1: 000000005a55d485 (&sb->s_type->i_mutex_key#25/1){+.+.}, at: do_unlinkat+0x3d8/0xa30 fs/namei.c:4059

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

NMI backtrace for cpu 1
CPU: 1 PID: 902 Comm: khungtaskd Not tainted 4.18.0-rc6+ #160
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+0x1c9/0x2b4 lib/dump_stack.c:113
nmi_cpu_backtrace.cold.4+0x19/0xce lib/nmi_backtrace.c:103
nmi_trigger_cpumask_backtrace+0x151/0x192 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:138 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:196 [inline]
watchdog+0x9c4/0xf80 kernel/hung_task.c:252
kthread+0x345/0x410 kernel/kthread.c:246
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0 skipped: idling at native_safe_halt+0x6/0x10 arch/x86/include/asm/irqflags.h:54

---
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 syzkaller@xxxxxxxxxxxxxxxxx

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

Next message: Jason Wang: "Re: [PATCH v2] vhost: introduce mdev based hardware backend"
Previous message: syzbot: "INFO: task hung in register_netdevice_notifier (2)"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]