INFO: task hung in switchdev_deferred_process_work

15 views
Skip to first unread message

syzbot

unread,
Mar 7, 2020, 11:06:14 PM3/7/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 7472c402 Linux 4.19.108
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=15377f29e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=6d889e71eea7bde
dashboard link: https://syzkaller.appspot.com/bug?extid=f8665ab78456deea5754
compiler: gcc (GCC) 9.0.0 20181231 (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+f8665a...@syzkaller.appspotmail.com

device bridge1506 left promiscuous mode
bond867 (unregistering): Released all slaves
bond866 (unregistering): Releasing active interface bridge1505
bond866 (unregistering): Releasing active interface bridge1504
device bridge1504 left promiscuous mode
INFO: task kworker/0:2:18439 blocked for more than 140 seconds.
Not tainted 4.19.108-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:2 D26616 18439 2 0x80000000
Workqueue: events switchdev_deferred_process_work
Call Trace:
schedule+0x8d/0x1b0 kernel/sched/core.c:3559
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3617
__mutex_lock_common kernel/locking/mutex.c:1002 [inline]
__mutex_lock+0x726/0x1300 kernel/locking/mutex.c:1072
switchdev_deferred_process_work+0xa/0x20 net/switchdev/switchdev.c:150
process_one_work+0x91f/0x1640 kernel/workqueue.c:2153
worker_thread+0x96/0xe20 kernel/workqueue.c:2296
kthread+0x34a/0x420 kernel/kthread.c:246
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
INFO: task kworker/1:0:12440 blocked for more than 140 seconds.
Not tainted 4.19.108-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/1:0 D26720 12440 2 0x80000000
Workqueue: events linkwatch_event
Call Trace:
schedule+0x8d/0x1b0 kernel/sched/core.c:3559
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3617
__mutex_lock_common kernel/locking/mutex.c:1002 [inline]
__mutex_lock+0x726/0x1300 kernel/locking/mutex.c:1072
linkwatch_event+0xb/0x60 net/core/link_watch.c:236
process_one_work+0x91f/0x1640 kernel/workqueue.c:2153
worker_thread+0x96/0xe20 kernel/workqueue.c:2296
kthread+0x34a/0x420 kernel/kthread.c:246
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
INFO: task syz-executor.0:18715 blocked for more than 140 seconds.
Not tainted 4.19.108-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.0 D24400 18715 1 0x00000004
Call Trace:
schedule+0x8d/0x1b0 kernel/sched/core.c:3559
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3617
__mutex_lock_common kernel/locking/mutex.c:1002 [inline]
__mutex_lock+0x726/0x1300 kernel/locking/mutex.c:1072
rtnl_lock net/core/rtnetlink.c:77 [inline]
rtnetlink_rcv_msg+0x3fe/0xaf0 net/core/rtnetlink.c:4774
netlink_rcv_skb+0x160/0x410 net/netlink/af_netlink.c:2455
netlink_unicast_kernel net/netlink/af_netlink.c:1318 [inline]
netlink_unicast+0x4d7/0x6a0 net/netlink/af_netlink.c:1344
netlink_sendmsg+0x80b/0xcd0 net/netlink/af_netlink.c:1909
sock_sendmsg_nosec net/socket.c:622 [inline]
sock_sendmsg+0xcf/0x120 net/socket.c:632
__sys_sendto+0x21a/0x330 net/socket.c:1787
__do_sys_sendto net/socket.c:1799 [inline]
__se_sys_sendto net/socket.c:1795 [inline]
__x64_sys_sendto+0xdd/0x1b0 net/socket.c:1795
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4161a3
Code: 90 90 90 90 90 90 90 48 83 ec 08 48 8b 05 55 1e 24 00 89 f9 48 8d 15 cc df 02 00 49 89 f0 be 01 00 00 00 48 8b 38 31 c0 e8 6a <56> ff ff 31 c0 48 83 c4 08 c3 0f 1f 00 48 8b 05 91 1a 24 00 48 89
RSP: 002b:00007ffeb9fcce38 EFLAGS: 00000246 ORIG_RAX: 000000000000002c
RAX: ffffffffffffffda RBX: 0000000000c82200 RCX: 00000000004161a3
RDX: 000000000000003c RSI: 0000000000c82250 RDI: 0000000000000003
RBP: 0000000000000000 R08: 00007ffeb9fcce40 R09: 000000000000000c
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000c82250 R15: 0000000000000003

Showing all locks held in the system:
1 lock held by khungtaskd/1073:
#0: 00000000bce85cff (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4436
1 lock held by rsyslogd/8034:
#0: 00000000d42a6884 (&f->f_pos_lock){+.+.}, at: __fdget_pos+0xe3/0x100 fs/file.c:767
2 locks held by getty/8159:
#0: 000000000b61a8dd (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:272
#1: 00000000a897ce94 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x217/0x1a50 drivers/tty/n_tty.c:2154
2 locks held by getty/8160:
#0: 00000000798c0435 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:272
#1: 000000009811c17c (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x217/0x1a50 drivers/tty/n_tty.c:2154
2 locks held by getty/8161:
#0: 000000007a5dd351 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:272
#1: 00000000e18da6f1 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x217/0x1a50 drivers/tty/n_tty.c:2154
2 locks held by getty/8162:
#0: 0000000066ad54ce (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:272
#1: 000000002f9c18da (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x217/0x1a50 drivers/tty/n_tty.c:2154
2 locks held by getty/8163:
#0: 0000000004366b28 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:272
#1: 000000005cc98b8a (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x217/0x1a50 drivers/tty/n_tty.c:2154
2 locks held by getty/8164:
#0: 00000000dbffcc96 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:272
#1: 00000000dfa9037b (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x217/0x1a50 drivers/tty/n_tty.c:2154
2 locks held by getty/24230:
#0: 00000000246904bb (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:272
#1: 00000000dc8b1458 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x217/0x1a50 drivers/tty/n_tty.c:2154
4 locks held by kworker/u4:7/557:
#0: 000000005da903b2 ((wq_completion)"%s""netns"){+.+.}, at: __write_once_size include/linux/compiler.h:220 [inline]
#0: 000000005da903b2 ((wq_completion)"%s""netns"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: 000000005da903b2 ((wq_completion)"%s""netns"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
#0: 000000005da903b2 ((wq_completion)"%s""netns"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:59 [inline]
#0: 000000005da903b2 ((wq_completion)"%s""netns"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
#0: 000000005da903b2 ((wq_completion)"%s""netns"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
#0: 000000005da903b2 ((wq_completion)"%s""netns"){+.+.}, at: process_one_work+0x81a/0x1640 kernel/workqueue.c:2124
#1: 00000000ffc7563e (net_cleanup_work){+.+.}, at: process_one_work+0x84e/0x1640 kernel/workqueue.c:2128
#2: 00000000f8dfdcdc (pernet_ops_rwsem){++++}, at: cleanup_net+0xa8/0x850 net/core/net_namespace.c:520
#3: 000000003eb0f01b (rtnl_mutex){+.+.}, at: rtnl_lock_unregistering net/core/dev.c:9718 [inline]
#3: 000000003eb0f01b (rtnl_mutex){+.+.}, at: default_device_exit_batch+0xea/0x3c0 net/core/dev.c:9756
3 locks held by kworker/0:2/18439:
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: __write_once_size include/linux/compiler.h:220 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:59 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: process_one_work+0x81a/0x1640 kernel/workqueue.c:2124
#1: 00000000a369b5f5 (deferred_process_work){+.+.}, at: process_one_work+0x84e/0x1640 kernel/workqueue.c:2128
#2: 000000003eb0f01b (rtnl_mutex){+.+.}, at: switchdev_deferred_process_work+0xa/0x20 net/switchdev/switchdev.c:150
3 locks held by kworker/0:3/19413:
#0: 00000000c8d005c6 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: __write_once_size include/linux/compiler.h:220 [inline]
#0: 00000000c8d005c6 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: 00000000c8d005c6 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
#0: 00000000c8d005c6 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:59 [inline]
#0: 00000000c8d005c6 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
#0: 00000000c8d005c6 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
#0: 00000000c8d005c6 ((wq_completion)"%s"("ipv6_addrconf")){+.+.}, at: process_one_work+0x81a/0x1640 kernel/workqueue.c:2124
#1: 00000000e8001496 ((addr_chk_work).work){+.+.}, at: process_one_work+0x84e/0x1640 kernel/workqueue.c:2128
#2: 000000003eb0f01b (rtnl_mutex){+.+.}, at: addrconf_verify_work+0xa/0x20 net/ipv6/addrconf.c:4466
3 locks held by kworker/1:0/12440:
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: __write_once_size include/linux/compiler.h:220 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:59 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
#0: 00000000149e0234 ((wq_completion)"events"){+.+.}, at: process_one_work+0x81a/0x1640 kernel/workqueue.c:2124
#1: 000000000da0a230 ((linkwatch_work).work){+.+.}, at: process_one_work+0x84e/0x1640 kernel/workqueue.c:2128
#2: 000000003eb0f01b (rtnl_mutex){+.+.}, at: linkwatch_event+0xb/0x60 net/core/link_watch.c:236
1 lock held by syz-executor.0/18715:
#0: 000000003eb0f01b (rtnl_mutex){+.+.}, at: rtnl_lock net/core/rtnetlink.c:77 [inline]
#0: 000000003eb0f01b (rtnl_mutex){+.+.}, at: rtnetlink_rcv_msg+0x3fe/0xaf0 net/core/rtnetlink.c:4774

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

bond866 (unregistering): Released all slaves
NMI backtrace for cpu 1
CPU: 1 PID: 1073 Comm: khungtaskd Not tainted 4.19.108-syzkaller #0
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+0x188/0x20d lib/dump_stack.c:118
nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
nmi_trigger_cpumask_backtrace+0x1a6/0x1eb 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+0x962/0xe40 kernel/hung_task.c:287
kthread+0x34a/0x420 kernel/kthread.c:246
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 1 to CPUs 0:
bond865 (unregistering): Releasing active interface bridge1503
NMI backtrace for cpu 0
CPU: 0 PID: 557 Comm: kworker/u4:7 Not tainted 4.19.108-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: netns cleanup_net
RIP: 0010:preempt_count arch/x86/include/asm/preempt.h:23 [inline]
RIP: 0010:check_kcov_mode kernel/kcov.c:67 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0xd/0x50 kernel/kcov.c:101
Code: 0a 41 bc f4 ff ff ff e8 4a 1e eb ff 48 c7 05 36 e9 05 0a 00 00 00 00 e9 24 ec ff ff 90 48 8b 34 24 65 48 8b 04 25 40 ee 01 00 <65> 8b 15 ec 4a 9a 7e 81 e2 00 01 1f 00 75 2b 8b 90 d0 12 00 00 83
RSP: 0018:ffff88803e6471a0 EFLAGS: 00000006
RAX: ffff888097a886c0 RBX: ffffffff876b3f67 RCX: ffffffff871a3fb0
RDX: 0000000000000030 RSI: ffffffff871a3fbe RDI: 0000000000000001
RBP: ffff88803e6472c0 R08: ffff888097a886c0 R09: fffffbfff11710c9
R10: fffffbfff11710c8 R11: ffffffff88b88643 R12: dffffc0000000000
R13: ffffffff876b3f65 R14: 1ffff11007cc8e38 R15: 0000000000000030
FS: 0000000000000000(0000) GS:ffff8880ae600000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000001b3b000 CR3: 0000000095820000 CR4: 00000000001406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
format_decode+0x18e/0xad0 lib/vsprintf.c:2029
vsnprintf+0x155/0x14f0 lib/vsprintf.c:2245
snprintf+0xbb/0xf0 lib/vsprintf.c:2426
print_time kernel/printk/printk.c:1234 [inline]
print_prefix+0x27f/0x3f0 kernel/printk/printk.c:1259
msg_print_text+0x82/0x1c0 kernel/printk/printk.c:1282
console_unlock+0x370/0xfe0 kernel/printk/printk.c:2403
vprintk_emit+0x282/0x6e0 kernel/printk/printk.c:1937
vprintk_func+0x79/0x17e kernel/printk/printk_safe.c:398
printk+0xba/0xed kernel/printk/printk.c:2012
__netdev_printk.cold+0x5c/0x61 net/core/dev.c:9610
netdev_info+0xd8/0x110 net/core/dev.c:9657
__bond_release_one+0x450/0x15c0 drivers/net/bonding/bond_main.c:1901
bond_slave_netdev_event drivers/net/bonding/bond_main.c:3113 [inline]
bond_netdev_event+0x980/0xb00 drivers/net/bonding/bond_main.c:3225
notifier_call_chain+0xc0/0x230 kernel/notifier.c:93
call_netdevice_notifiers net/core/dev.c:1766 [inline]
rollback_registered_many+0x7bc/0xc40 net/core/dev.c:8180
unregister_netdevice_many.part.0+0x16/0x1e0 net/core/dev.c:9294
unregister_netdevice_many net/core/dev.c:9293 [inline]
default_device_exit_batch+0x2ff/0x3c0 net/core/dev.c:9765
ops_exit_list.isra.0+0xef/0x140 net/core/net_namespace.c:156
cleanup_net+0x3bf/0x850 net/core/net_namespace.c:553
process_one_work+0x91f/0x1640 kernel/workqueue.c:2153
worker_thread+0x96/0xe20 kernel/workqueue.c:2296
kthread+0x34a/0x420 kernel/kthread.c:246
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415


---
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#status for how to communicate with syzbot.
Reply all
Reply to author
Forward
0 new messages