INFO: task hung in blkdev

INFO: task hung in blkdev_put (4)
Status: upstream: reported C repro on 2020/10/03 13:09
Reported-by: syzbot+9a29d5e745bd7523c851@syzkaller.appspotmail.com
First crash: 230d, last: 6d03h

Cause bisection: introduced by (bisect log) :
commit 2da22da573481cc4837e246d0eee4d518b3f715e
Author: Mike Christie <mchristi@redhat.com>
Date: Tue Aug 13 16:39:52 2019 +0000

nbd: fix zero cmd timeout handling v2

Crash: INFO: task hung in blkdev_put (log)
Repro: C syz .config

similar bugs (12):
Kernel	Title	Repro	Count	Last	Reported	Patched	Status
upstream	INFO: task hung in blkdev_put (3)		1	309d	309d	0/21	auto-closed as invalid on 2020/06/25 13:28
android-49	INFO: task hung in blkdev_put (2)		3	472d	492d	0/3	auto-closed as invalid on 2020/03/14 12:22
linux-4.19	INFO: task hung in blkdev_put	C	10	5d23h	221d	0/1	upstream: reported C repro on 2020/07/23 21:33
upstream	INFO: task hung in blkdev_put		320	751d	1177d	0/21	closed as dup on 2018/11/11 08:29
linux-4.14	INFO: task hung in blkdev_put		2	535d	684d	0/1	auto-closed as invalid on 2020/01/12 01:56
linux-4.14	INFO: task hung in blkdev_put (3)	C	8	28d	183d	0/1	upstream: reported C repro on 2020/08/30 21:52
android-49	INFO: task hung in blkdev_put		220	670d	687d	0/3	auto-closed as invalid on 2019/10/25 08:47
linux-4.14	INFO: task hung in blkdev_put (2)		2	338d	376d	0/1	auto-closed as invalid on 2020/07/26 14:38
android-414	INFO: task hung in blkdev_put		119	457d	689d	0/1	auto-closed as invalid on 2020/03/30 04:06
android-44	INFO: task hung in blkdev_put		26	757d	687d	0/2	auto-closed as invalid on 2019/08/03 02:42
android-44	INFO: task hung in blkdev_put (2)		3	468d	545d	0/2	auto-closed as invalid on 2020/03/18 19:27
upstream	INFO: task hung in blkdev_put (2)		2	464d	509d	0/21	auto-closed as invalid on 2020/02/22 04:07

Sample crash report:

INFO: task syz-executor056:8418 blocked for more than 143 seconds.
      Not tainted 5.11.0-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor056 state:D stack:27424 pid: 8418 ppid:  8417 flags:0x00004006
Call Trace:
 context_switch kernel/sched/core.c:4327 [inline]
 __schedule+0x90c/0x21a0 kernel/sched/core.c:5078
 schedule+0xcf/0x270 kernel/sched/core.c:5157
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:5216
 __mutex_lock_common kernel/locking/mutex.c:1033 [inline]
 __mutex_lock+0x81a/0x1110 kernel/locking/mutex.c:1103
 blkdev_put+0x59/0x570 fs/block_dev.c:1591
 blkdev_close+0x8c/0xb0 fs/block_dev.c:1640
 __fput+0x283/0x920 fs/file_table.c:280
 task_work_run+0xdd/0x190 kernel/task_work.c:140
 exit_task_work include/linux/task_work.h:30 [inline]
 do_exit+0xc5c/0x2ae0 kernel/exit.c:825
 do_group_exit+0x125/0x310 kernel/exit.c:922
 get_signal+0x427/0x20f0 kernel/signal.c:2773
 arch_do_signal_or_restart+0x2a8/0x1eb0 arch/x86/kernel/signal.c:811
 handle_signal_work kernel/entry/common.c:147 [inline]
 exit_to_user_mode_loop kernel/entry/common.c:171 [inline]
 exit_to_user_mode_prepare+0x148/0x250 kernel/entry/common.c:201
 __syscall_exit_to_user_mode_work kernel/entry/common.c:283 [inline]
 syscall_exit_to_user_mode+0x19/0x50 kernel/entry/common.c:294
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x444519
RSP: 002b:00007fffb8a140c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: fffffffffffffe00 RBX: 00000000004004a0 RCX: 0000000000444519
RDX: 0000000000000000 RSI: 000000000000ab03 RDI: 0000000000000006
RBP: 0000000000000000 R08: 002364626e2f7665 R09: 00007fffb8a14268
R10: 000000000000000f R11: 0000000000000246 R12: 00000000004035a0
R13: 431bde82d7b634db R14: 00000000004b2018 R15: 00000000004004a0
INFO: task systemd-udevd:8422 blocked for more than 143 seconds.
      Not tainted 5.11.0-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:systemd-udevd   state:D stack:26320 pid: 8422 ppid:  4870 flags:0x00004004
Call Trace:
 context_switch kernel/sched/core.c:4327 [inline]
 __schedule+0x90c/0x21a0 kernel/sched/core.c:5078
 schedule+0xcf/0x270 kernel/sched/core.c:5157
 io_schedule+0xba/0x130 kernel/sched/core.c:6852
 wait_on_page_bit_common+0x424/0xeb0 mm/filemap.c:1277
 wait_on_page_bit mm/filemap.c:1338 [inline]
 wait_on_page_locked include/linux/pagemap.h:674 [inline]
 wait_on_page_read mm/filemap.c:3065 [inline]
 do_read_cache_page+0x957/0x1390 mm/filemap.c:3108
 read_mapping_page include/linux/pagemap.h:500 [inline]
 read_part_sector+0x140/0x610 block/partitions/core.c:695
 adfspart_check_ICS+0x9d/0xc90 block/partitions/acorn.c:360
 check_partition block/partitions/core.c:150 [inline]
 blk_add_partitions+0x57c/0xf10 block/partitions/core.c:623
 bdev_disk_changed+0x1fd/0x410 fs/block_dev.c:1259
 __blkdev_get+0x83c/0xa00 fs/block_dev.c:1341
 blkdev_get_by_dev fs/block_dev.c:1445 [inline]
 blkdev_get_by_dev+0x260/0x5e0 fs/block_dev.c:1413
 blkdev_open+0x154/0x2b0 fs/block_dev.c:1542
 do_dentry_open+0x4b9/0x11b0 fs/open.c:817
 do_open fs/namei.c:3254 [inline]
 path_openat+0x1b9a/0x2730 fs/namei.c:3371
 do_filp_open+0x17e/0x3c0 fs/namei.c:3398
 do_sys_openat2+0x16d/0x420 fs/open.c:1172
 do_sys_open fs/open.c:1188 [inline]
 __do_sys_open fs/open.c:1196 [inline]
 __se_sys_open fs/open.c:1192 [inline]
 __x64_sys_open+0x119/0x1c0 fs/open.c:1192
 do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7f244eff9840
RSP: 002b:00007ffe8717ce58 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 00005622c0333910 RCX: 00007f244eff9840
RDX: 00005622be811fe3 RSI: 00000000000a0800 RDI: 00005622c0343840
RBP: 00007ffe8717cfd0 R08: 00005622be811670 R09: 0000000000000010
R10: 00005622be811d0c R11: 0000000000000246 R12: 00007ffe8717cf20
R13: 00005622c0344cc0 R14: 0000000000000003 R15: 000000000000000e

Showing all locks held in the system:
1 lock held by khungtaskd/1648:
 #0: ffffffff8bd73da0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:6259
2 locks held by in:imklog/8119:
 #0: ffff88802a8043b0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100 fs/file.c:947
 #1: ffff8880b9d34d18 (&rq->lock){-.-.}-{2:2}, at: rq_lock kernel/sched/sched.h:1320 [inline]
 #1: ffff8880b9d34d18 (&rq->lock){-.-.}-{2:2}, at: __schedule+0x217/0x21a0 kernel/sched/core.c:4995
1 lock held by syz-executor056/8418:
 #0: ffff888017a85420 (&bdev->bd_mutex){+.+.}-{3:3}, at: blkdev_put+0x59/0x570 fs/block_dev.c:1591
1 lock held by systemd-udevd/8422:
 #0: ffff888017a85420 (&bdev->bd_mutex){+.+.}-{3:3}, at: blkdev_get_by_dev fs/block_dev.c:1444 [inline]
 #0: ffff888017a85420 (&bdev->bd_mutex){+.+.}-{3:3}, at: blkdev_get_by_dev+0x255/0x5e0 fs/block_dev.c:1413

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

NMI backtrace for cpu 0
CPU: 0 PID: 1648 Comm: khungtaskd Not tainted 5.11.0-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:79 [inline]
 dump_stack+0x107/0x163 lib/dump_stack.c:120
 nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
 nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:209 [inline]
 watchdog+0xd43/0xfa0 kernel/hung_task.c:294
 kthread+0x3b1/0x4a0 kernel/kthread.c:292
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:296
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 4863 Comm: systemd-journal Not tainted 5.11.0-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:unwind_next_frame+0x12ae/0x1f90 arch/x86/kernel/unwind_orc.c:584
Code: 40 48 89 f8 48 c1 e8 03 0f b6 34 08 49 8d 40 03 49 89 c1 49 c1 e9 03 41 0f b6 0c 09 49 89 f9 41 83 e1 07 44 38 ce 41 0f 9e c1 <40> 84 f6 40 0f 95 c6 41 84 f1 0f 85 fa 08 00 00 83 e0 07 38 c1 40
RSP: 0018:ffffc90001267970 EFLAGS: 00000246
RAX: ffffffff8e2597b1 RBX: 1ffff9200024cf36 RCX: 0000000000000000
RDX: ffffc90001267a88 RSI: 0000000000000000 RDI: ffffffff8e2597b0
RBP: 0000000000000001 R08: ffffffff8e2597ae R09: 0000000000000001
R10: 0000000000082083 R11: 0000000000000001 R12: ffffc90001267db8
R13: ffffc90001267a7d R14: ffffc90001267a98 R15: ffffc90001267a48
FS:  00007f5961fc98c0(0000) GS:ffff8880b9d00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f595f3b6018 CR3: 000000001504b000 CR4: 00000000001506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 arch_stack_walk+0x7d/0xe0 arch/x86/kernel/stacktrace.c:25
 stack_trace_save+0x8c/0xc0 kernel/stacktrace.c:121
 kasan_save_stack+0x1b/0x40 mm/kasan/common.c:38
 kasan_set_track mm/kasan/common.c:46 [inline]
 set_alloc_info mm/kasan/common.c:401 [inline]
 ____kasan_kmalloc.constprop.0+0x7f/0xa0 mm/kasan/common.c:429
 kasan_slab_alloc include/linux/kasan.h:209 [inline]
 slab_post_alloc_hook mm/slab.h:512 [inline]
 slab_alloc mm/slab.c:3315 [inline]
 kmem_cache_alloc+0x1ab/0x4c0 mm/slab.c:3486
 getname_flags.part.0+0x50/0x4f0 fs/namei.c:138
 getname_flags fs/namei.c:2649 [inline]
 user_path_at_empty+0xa1/0x100 fs/namei.c:2649
 user_path_at include/linux/namei.h:59 [inline]
 do_faccessat+0x129/0x820 fs/open.c:423
 do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x7f59612849c7
Code: 83 c4 08 48 3d 01 f0 ff ff 73 01 c3 48 8b 0d c8 d4 2b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 b8 15 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a1 d4 2b 00 f7 d8 64 89 01 48
RSP: 002b:00007ffdf0785dd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000015
RAX: ffffffffffffffda RBX: 00007ffdf0788cf0 RCX: 00007f59612849c7
RDX: 00007f5961cf5a00 RSI: 0000000000000000 RDI: 000055ab81cc89a3
RBP: 00007ffdf0785e10 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000069 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: 00007ffdf0788cf0 R15: 00007ffdf0786300

Fix bisection attempts:
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report	Syz repro	C repro	VM info	Title
ci-upstream-kasan-gce-selinux-root	2021/01/19 15:55	upstream	1e2a199f	1b88c6d5	.config	log	report	syz	C
ci-upstream-kasan-gce-selinux-root	2020/12/20 13:50	upstream	467f8165	1b88c6d5	.config	log	report	syz	C

Crashes (18):
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report	Syz repro	C repro	VM info	Title
ci-upstream-kasan-gce-selinux-root	2021/02/19 12:37	upstream	f40ddce8	14052202	.config	log	report	syz	C		INFO: task hung in blkdev_put
ci-upstream-kasan-gce-smack-root	2021/02/15 14:00	upstream	f40ddce8	98682e5e	.config	log	report	syz	C		INFO: task hung in blkdev_put
ci-upstream-kasan-gce-root	2021/02/09 10:07	upstream	e0756cfc	2bd9619f	.config	log	report	syz	C		INFO: task hung in blkdev_put
ci-upstream-linux-next-kasan-gce-root	2021/01/21 20:42	linux-next	bc085f8f	d4f4eca5	.config	log	report	syz	C		INFO: task hung in blkdev_put
ci-upstream-kasan-gce-selinux-root	2020/09/29 13:03	upstream	fb0155a0	1b88c6d5	.config	log	report	syz	C
ci-upstream-linux-next-kasan-gce-root	2020/10/30 23:57	linux-next	4e78c578	a6e3ac3b	.config	log	report	syz	C
ci-upstream-kasan-gce-root	2021/02/24 02:32	upstream	3b9cdafb	fcc6d71b	.config	log	report			info	INFO: task hung in blkdev_put
ci-upstream-kasan-gce-smack-root	2021/02/19 12:57	upstream	f40ddce8	14052202	.config	log	report			info	INFO: task hung in blkdev_put
ci-upstream-kasan-gce-smack-root	2021/01/21 01:31	upstream	75439bc4	d4f4eca5	.config	log	report			info	INFO: task hung in blkdev_put
ci-upstream-kasan-gce-selinux-root	2020/11/20 05:59	upstream	131ad0b6	0767f13f	.config	log	report			info
ci-upstream-kasan-gce-selinux-root	2020/11/20 05:59	upstream	131ad0b6	0767f13f	.config	log	report			info
ci-upstream-kasan-gce-selinux-root	2020/11/20 05:58	upstream	131ad0b6	0767f13f	.config	log	report			info
ci-upstream-kasan-gce-root	2020/11/20 05:58	upstream	3494d588	0767f13f	.config	log	report			info
ci-upstream-kasan-gce-selinux-root	2020/10/10 21:49	upstream	6f2f486d	4a77ae0b	.config	log	report			info
ci-upstream-kasan-gce-root	2020/10/09 10:33	upstream	3d006ee4	92390980	.config	log	report			info
ci-upstream-kasan-gce-root	2020/07/19 03:32	upstream	6a70f89c	9c812472	.config	log	report
ci-upstream-kasan-gce-root	2020/07/14 17:36	upstream	0dc589da	ce4c95b3	.config	log	report
ci-upstream-linux-next-kasan-gce-root	2020/11/20 08:20	linux-next	95065cb5	0767f13f	.config	log	report			info