INFO: task hung in __writeback_inodes_sb_nr

5 views
Skip to first unread message

syzbot

unread,
Sep 28, 2022, 5:19:35 PM9/28/22
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: 3f8a27f9e27b Linux 4.19.211
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=1192eaa8880000
kernel config: https://syzkaller.appspot.com/x/.config?x=9b9277b418617afe
dashboard link: https://syzkaller.appspot.com/bug?extid=339acf8d39fdf57de40f
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)

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

Downloadable assets:
disk image: https://storage.googleapis.com/98c0bdb4abb3/disk-3f8a27f9.raw.xz
vmlinux: https://storage.googleapis.com/ea228ff02669/vmlinux-3f8a27f9.xz

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

ieee802154 phy1 wpan1: encryption failed: -22
ieee802154 phy0 wpan0: encryption failed: -22
ieee802154 phy1 wpan1: encryption failed: -22
ieee802154 phy0 wpan0: encryption failed: -22
ieee802154 phy1 wpan1: encryption failed: -22
INFO: task syz-executor.5:8155 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.5 D24208 8155 8145 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
wb_wait_for_completion+0x175/0x1f0 fs/fs-writeback.c:222
__writeback_inodes_sb_nr+0x1df/0x270 fs/fs-writeback.c:2373
__sync_filesystem fs/sync.c:36 [inline]
sync_filesystem+0xb2/0x250 fs/sync.c:64
ovl_sync_fs+0xb1/0xf0 fs/overlayfs/super.c:284
__sync_filesystem fs/sync.c:39 [inline]
sync_filesystem+0x1b5/0x250 fs/sync.c:67
generic_shutdown_super+0x70/0x370 fs/super.c:442
kill_anon_super+0x36/0x60 fs/super.c:1032
deactivate_locked_super+0x94/0x160 fs/super.c:329
deactivate_super+0x174/0x1a0 fs/super.c:360
cleanup_mnt+0x1a8/0x290 fs/namespace.c:1098
task_work_run+0x148/0x1c0 kernel/task_work.c:113
tracehook_notify_resume include/linux/tracehook.h:193 [inline]
exit_to_usermode_loop+0x251/0x2a0 arch/x86/entry/common.c:167
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x538/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f7e37db1a17
Code: Bad RIP value.
RSP: 002b:00007ffe0ea730d8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a6
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f7e37db1a17
RDX: 00007ffe0ea731a9 RSI: 000000000000000a RDI: 00007ffe0ea731a0
RBP: 00007ffe0ea731a0 R08: 00000000ffffffff R09: 00007ffe0ea72f70
R10: 0000555556a71903 R11: 0000000000000246 R12: 00007f7e37e0a5f6
R13: 00007ffe0ea74260 R14: 0000555556a71810 R15: 00007ffe0ea742a0
INFO: task kworker/0:3:9357 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:3 D26024 9357 2 0x80000000
Workqueue: events switchdev_deferred_process_work
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3619
__mutex_lock_common kernel/locking/mutex.c:1016 [inline]
__mutex_lock+0x5f0/0x1190 kernel/locking/mutex.c:1078
switchdev_deferred_process_work+0xa/0x20 net/switchdev/switchdev.c:150
process_one_work+0x864/0x1570 kernel/workqueue.c:2153
worker_thread+0x64c/0x1130 kernel/workqueue.c:2296
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
INFO: task kworker/0:4:9358 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:4 D29368 9358 2 0x80000000
Workqueue: ipv6_addrconf addrconf_verify_work
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3619
__mutex_lock_common kernel/locking/mutex.c:1016 [inline]
__mutex_lock+0x5f0/0x1190 kernel/locking/mutex.c:1078
addrconf_verify_work+0xa/0x20 net/ipv6/addrconf.c:4476
process_one_work+0x864/0x1570 kernel/workqueue.c:2153
worker_thread+0x64c/0x1130 kernel/workqueue.c:2296
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
INFO: task kworker/u4:12:10958 blocked for more than 140 seconds.
Not tainted 4.19.211-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u4:12 D26048 10958 2 0x80000000
Workqueue: netns cleanup_net
Call Trace:
context_switch kernel/sched/core.c:2828 [inline]
__schedule+0x887/0x2040 kernel/sched/core.c:3517
schedule+0x8d/0x1b0 kernel/sched/core.c:3561
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3619
__mutex_lock_common kernel/locking/mutex.c:1016 [inline]
__mutex_lock+0x5f0/0x1190 kernel/locking/mutex.c:1078
cangw_pernet_exit+0xe/0x20 net/can/gw.c:1032
ops_exit_list+0xa5/0x150 net/core/net_namespace.c:153
cleanup_net+0x3b4/0x8b0 net/core/net_namespace.c:554
process_one_work+0x864/0x1570 kernel/workqueue.c:2153
worker_thread+0x64c/0x1130 kernel/workqueue.c:2296
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415

Showing all locks held in the system:
1 lock held by systemd/1:
3 locks held by kworker/u4:2/92:
1 lock held by khungtaskd/1514:
#0: 000000006de51b41 (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4441
1 lock held by systemd-journal/4688:
1 lock held by systemd-timesyn/6158:
1 lock held by in:imklog/7814:
#0: 000000007be09884 (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
1 lock held by cron/7786:
4 locks held by syz-executor.2/8146:
1 lock held by syz-executor.0/8151:
2 locks held by syz-executor.5/8155:
#0: 000000008de820b4 (&type->s_umount_key#52){+.+.}, at: deactivate_super+0x16c/0x1a0 fs/super.c:359
#1: 00000000fc59c530 (&type->s_umount_key#35){++++}, at: ovl_sync_fs+0xa9/0xf0 fs/overlayfs/super.c:283
4 locks held by kworker/0:0/8242:
2 locks held by kworker/u4:5/8843:
3 locks held by kworker/0:3/9357:
#0: 0000000064e8e288 ((wq_completion)"events"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
#1: 0000000048b66c7d (deferred_process_work){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
#2: 0000000019cd5dc0 (rtnl_mutex){+.+.}, at: switchdev_deferred_process_work+0xa/0x20 net/switchdev/switchdev.c:150
3 locks held by kworker/0:4/9358:
#0: 000000001db90254 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
#1: 000000008bf5df6d ((addr_chk_work).work){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
#2: 0000000019cd5dc0 (rtnl_mutex){+.+.}, at: addrconf_verify_work+0xa/0x20 net/ipv6/addrconf.c:4476
2 locks held by kworker/u4:11/10938:
#0: 000000008d7882ad ((wq_completion)"events_unbound"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
#1: 000000002b043bd2 (connector_reaper_work){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
4 locks held by kworker/u4:12/10958:
#0: 00000000653f0bc1 ((wq_completion)"%s""netns"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
#1: 0000000044bc07ad (net_cleanup_work){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
#2: 00000000f5ddcb07 (pernet_ops_rwsem){++++}, at: cleanup_net+0xa8/0x8b0 net/core/net_namespace.c:521
#3: 0000000019cd5dc0 (rtnl_mutex){+.+.}, at: cangw_pernet_exit+0xe/0x20 net/can/gw.c:1032
2 locks held by syz-executor.0/6615:
1 lock held by kworker/u4:11/6633:

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

NMI backtrace for cpu 1
CPU: 1 PID: 1514 Comm: khungtaskd Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 08/26/2022
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1fc/0x2ef lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1a6/0x1f0 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
watchdog+0x991/0xe60 kernel/hung_task.c:287
kthread+0x33f/0x460 kernel/kthread.c:259
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 6158 Comm: systemd-timesyn Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 08/26/2022
RIP: 0010:fs_reclaim_acquire+0x0/0x130 mm/page_alloc.c:3768
Code: 36 ca cc ff 5b 5d c3 e8 0e e2 19 00 e9 44 ff ff ff e8 04 e2 19 00 e9 77 ff ff ff e8 fa e1 19 00 eb b6 0f 1f 84 00 00 00 00 00 <55> 65 48 8b 04 25 c0 df 01 00 48 89 e5 41 56 49 89 c6 53 89 fb 48
RSP: 0018:ffff8880ba007ca0 EFLAGS: 00000202
RAX: ffff888097ef2240 RBX: 0000000000480020 RCX: ffffffff86709872
RDX: 00000000ffffffff RSI: 0000000000480020 RDI: 0000000000480020
RBP: ffff8880b5b8fd80 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000005 R11: 0000000000000000 R12: 00000000ffffffff
R13: 0000000000000000 R14: 0000000000480020 R15: ffff88809a128f78
FS: 00007f0eebf9a8c0(0000) GS:ffff8880ba000000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fbf792b4718 CR3: 00000000954d3000 CR4: 00000000003406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Call Trace:
<IRQ>
slab_pre_alloc_hook mm/slab.h:419 [inline]
slab_alloc_node mm/slab.c:3304 [inline]
kmem_cache_alloc_node+0x33/0x3b0 mm/slab.c:3647
__alloc_skb+0x71/0x560 net/core/skbuff.c:193
alloc_skb include/linux/skbuff.h:995 [inline]
bcm_can_tx+0x259/0x800 net/can/bcm.c:287
bcm_tx_timeout_tsklet+0x1f0/0x3a0 net/can/bcm.c:414
tasklet_action_common.constprop.0+0x265/0x360 kernel/softirq.c:522
__do_softirq+0x265/0x980 kernel/softirq.c:292
invoke_softirq kernel/softirq.c:372 [inline]
irq_exit+0x215/0x260 kernel/softirq.c:412
exiting_irq arch/x86/include/asm/apic.h:536 [inline]
smp_apic_timer_interrupt+0x136/0x550 arch/x86/kernel/apic/apic.c:1098
apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:894
</IRQ>
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:789 [inline]
RIP: 0010:qlink_free mm/kasan/quarantine.c:150 [inline]
RIP: 0010:qlist_free_all+0xfc/0x140 mm/kasan/quarantine.c:166
Code: 50 08 48 8d 4a ff 83 e2 01 48 0f 45 c1 4c 8b 70 18 e9 40 ff ff ff e8 a3 36 cf ff 48 83 3d e3 0f 59 08 00 74 38 4c 89 ff 57 9d <0f> 1f 44 00 00 4d 85 e4 75 9e 49 c7 45 08 00 00 00 00 49 c7 45 00
RSP: 0018:ffff888097eff9e0 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff13
RAX: 0000000000000007 RBX: ffff888054e90a40 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffff888097ef2ac8 RDI: 0000000000000286
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff888054e91b80
R13: ffff888097effa18 R14: ffff88813bff0940 R15: 0000000000000286
quarantine_reduce+0x1a9/0x230 mm/kasan/quarantine.c:259
kasan_kmalloc+0xa2/0x160 mm/kasan/kasan.c:538
slab_post_alloc_hook mm/slab.h:445 [inline]
slab_alloc mm/slab.c:3397 [inline]
kmem_cache_alloc_trace+0x11a/0x380 mm/slab.c:3623
kmalloc include/linux/slab.h:515 [inline]
kzalloc include/linux/slab.h:709 [inline]
apparmor_sk_alloc_security+0x5c/0xe0 security/apparmor/lsm.c:769
security_sk_alloc+0x50/0xb0 security/security.c:1469
sk_prot_alloc+0xf1/0x2d0 net/core/sock.c:1486
sk_alloc+0x36/0xec0 net/core/sock.c:1537
unix_create1+0xbc/0x530 net/unix/af_unix.c:807
unix_create+0xf9/0x1e0 net/unix/af_unix.c:868
__sock_create+0x3d8/0x740 net/socket.c:1365
sock_create net/socket.c:1416 [inline]
__sys_socket+0xef/0x200 net/socket.c:1458
__do_sys_socket net/socket.c:1467 [inline]
__se_sys_socket net/socket.c:1465 [inline]
__x64_sys_socket+0x6f/0xb0 net/socket.c:1465
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f0eeb38ff17
Code: 73 01 c3 48 8b 0d 81 ef 2a 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 29 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 51 ef 2a 00 f7 d8 64 89 01 48
RSP: 002b:00007ffc9da5c778 EFLAGS: 00000246 ORIG_RAX: 0000000000000029
RAX: ffffffffffffffda RBX: 00007f0eebca1c05 RCX: 00007f0eeb38ff17
RDX: 0000000000000000 RSI: 0000000000080002 RDI: 0000000000000001
RBP: 00007ffc9da5c8b0 R08: 0000000000000000 R09: 000001186248ff19
R10: 00007ffc9da5cf55 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000000 R15: 00007ffc9da5c7b0


---
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.
Reply all
Reply to author
Forward
0 new messages