Re: INFO: task hung in unregister_netdevice_notifier (3)

From: Oliver Hartkopp
Date: Mon Jul 15 2019 - 13:23:08 EST


Hello all,

On 14.07.19 06:07, syzbot wrote:
syzbot has found a reproducer for the following crash on:

the internal users of the CAN networking subsystem like CAN_BCM and CAN_RAW hold a number of CAN identifier subscriptions ('filters') for CAN netdevices (only type ARPHRD_CAN) in their socket data structures.

The per-socket netdevice notifier is used to manage the ad-hoc removal of these filters at netdevice removal time.

What I can see in the console output at

https://syzkaller.appspot.com/x/log.txt?x=10e45f0fa00000

seems to be a race between an unknown register_netdevice_notifier() call ("A") and the unregister_netdevice_notifier() ("B") likely invoked by bcm_release() ("C"):

[ 1047.294207][ T1049] schedule+0xa8/0x270
[ 1047.318401][ T1049] rwsem_down_write_slowpath+0x70a/0xf70
[ 1047.324114][ T1049] ? downgrade_write+0x3c0/0x3c0
[ 1047.438644][ T1049] ? mark_held_locks+0xf0/0xf0
[ 1047.443483][ T1049] ? lock_acquire+0x190/0x410
[ 1047.448191][ T1049] ? unregister_netdevice_notifier+0x7e/0x390
[ 1047.547227][ T1049] down_write+0x13c/0x150
[ 1047.579535][ T1049] ? down_write+0x13c/0x150
[ 1047.584106][ T1049] ? __down_timeout+0x2d0/0x2d0
[ 1047.635356][ T1049] ? mark_held_locks+0xf0/0xf0
[ 1047.640721][ T1049] unregister_netdevice_notifier+0x7e/0x390 <- "B"
[ 1047.646667][ T1049] ? __sock_release+0x89/0x280
[ 1047.709126][ T1049] ? register_netdevice_notifier+0x630/0x630 <- "A"
[ 1047.715203][ T1049] ? __kasan_check_write+0x14/0x20
[ 1047.775138][ T1049] bcm_release+0x93/0x5e0 <- "C"
[ 1047.795337][ T1049] __sock_release+0xce/0x280
[ 1047.829016][ T1049] sock_close+0x1e/0x30

The question to me is now:

Is the problem located in an (un)register_netdevice_notifier race OR is it generally a bad idea to call unregister_netdevice_notifier() in a sock release?

I've never seen that kind of problem in the wild. But if it would be the latter case wouldn't it be the same problem when someone unloads the kernel module at the 'wrong' time?

In commit 328fbe747ad46 ("net: Close race between {un, }register_netdevice_notifier() and setup_net()/cleanup_net()") Kirill Tkhai reviewed the calling site in CAN_RAW raw_release() which points to the same situation. Therefore added him to the recipient list.

Should down_write() be replaced with something like rwsem_down_write_slowpath()??

Regards,
Oliver

HEAD commit:ÂÂÂ a2d79c71 Merge tag 'for-5.3/io_uring-20190711' of git://gi..
git tree:ÂÂÂÂÂÂ upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=10e45f0fa00000
kernel config:Â https://syzkaller.appspot.com/x/.config?x=3539b1747f03988e
dashboard link: https://syzkaller.appspot.com/bug?extid=0f1827363a305f74996f
compiler:ÂÂÂÂÂÂ gcc (GCC) 9.0.0 20181231 (experimental)
syz repro:ÂÂÂÂÂ https://syzkaller.appspot.com/x/repro.syz?x=1765c52fa00000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+0f1827363a305f74996f@xxxxxxxxxxxxxxxxxxxxxxxxx

INFO: task syz-executor.4:9527 blocked for more than 143 seconds.
ÂÂÂÂÂ Not tainted 5.2.0+ #80
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.4Â D28136Â 9527ÂÂ 9356 0x00000004
Call Trace:
Âcontext_switch kernel/sched/core.c:3252 [inline]
Â__schedule+0x755/0x1580 kernel/sched/core.c:3878
Âschedule+0xa8/0x270 kernel/sched/core.c:3942
Ârwsem_down_write_slowpath+0x70a/0xf70 kernel/locking/rwsem.c:1198
Â__down_write kernel/locking/rwsem.c:1349 [inline]
Âdown_write+0x13c/0x150 kernel/locking/rwsem.c:1485
Âunregister_netdevice_notifier+0x7e/0x390 net/core/dev.c:1713
Âbcm_release+0x93/0x5e0 net/can/bcm.c:1525
Â__sock_release+0xce/0x280 net/socket.c:586
Âsock_close+0x1e/0x30 net/socket.c:1264
Â__fput+0x2ff/0x890 fs/file_table.c:280
Â____fput+0x16/0x20 fs/file_table.c:313
Âtask_work_run+0x145/0x1c0 kernel/task_work.c:113
Âtracehook_notify_resume include/linux/tracehook.h:185 [inline]
Âexit_to_usermode_loop+0x316/0x380 arch/x86/entry/common.c:163
Âprepare_exit_to_usermode arch/x86/entry/common.c:194 [inline]
Âsyscall_return_slowpath arch/x86/entry/common.c:274 [inline]
Âdo_syscall_64+0x5a9/0x6a0 arch/x86/entry/common.c:299
Âentry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x413501
Code: 75 14 b8 03 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 04 1b 00 00 c3 48 83 ec 08 e8 0a fc ff ff 48 89 04 24 b8 03 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 53 fc ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:0000000000a6fbc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000413501
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
RBP: 0000000000000001 R08: ffffffffffffffff R09: ffffffffffffffff
R10: 0000000000a6fca0 R11: 0000000000000293 R12: 000000000075c9a0
R13: 000000000075c9a0 R14: 00000000007619c8 R15: ffffffffffffffff
INFO: task syz-executor.2:9528 blocked for more than 145 seconds.
ÂÂÂÂÂ Not tainted 5.2.0+ #80
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.2Â D28136Â 9528ÂÂ 9354 0x00000004
Call Trace:
Âcontext_switch kernel/sched/core.c:3252 [inline]
Â__schedule+0x755/0x1580 kernel/sched/core.c:3878
Âschedule+0xa8/0x270 kernel/sched/core.c:3942
Ârwsem_down_write_slowpath+0x70a/0xf70 kernel/locking/rwsem.c:1198
Â__down_write kernel/locking/rwsem.c:1349 [inline]
Âdown_write+0x13c/0x150 kernel/locking/rwsem.c:1485
Âunregister_netdevice_notifier+0x7e/0x390 net/core/dev.c:1713
Âbcm_release+0x93/0x5e0 net/can/bcm.c:1525
Â__sock_release+0xce/0x280 net/socket.c:586
Âsock_close+0x1e/0x30 net/socket.c:1264
Â__fput+0x2ff/0x890 fs/file_table.c:280
Â____fput+0x16/0x20 fs/file_table.c:313
Âtask_work_run+0x145/0x1c0 kernel/task_work.c:113
Âtracehook_notify_resume include/linux/tracehook.h:185 [inline]
Âexit_to_usermode_loop+0x316/0x380 arch/x86/entry/common.c:163
Âprepare_exit_to_usermode arch/x86/entry/common.c:194 [inline]
Âsyscall_return_slowpath arch/x86/entry/common.c:274 [inline]
Âdo_syscall_64+0x5a9/0x6a0 arch/x86/entry/common.c:299
Âentry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x413501
Code: 5f fe ff ff 31 c9 31 f6 41 b9 b0 20 41 00 41 b8 8c d6 65 00 ba 02 00 00 00 bf 28 38 44 00 ff 15 7d a1 24 00 85 c0 0f 85 37 fe <ff> ff 31 c9 31 f6 41 b9 b0 20 41 00 41 b8 90 d6 65 00 ba 03 00 00
RSP: 002b:0000000000a6fbc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000413501
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
RBP: 0000000000000001 R08: ffffffffffffffff R09: ffffffffffffffff
R10: 0000000000a6fca0 R11: 0000000000000293 R12: 000000000075c9a0
R13: 000000000075c9a0 R14: 00000000007619c8 R15: ffffffffffffffff
INFO: task syz-executor.0:9529 blocked for more than 147 seconds.
ÂÂÂÂÂ Not tainted 5.2.0+ #80
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.0Â D28136Â 9529ÂÂ 9353 0x00000004
Call Trace:
Âcontext_switch kernel/sched/core.c:3252 [inline]
Â__schedule+0x755/0x1580 kernel/sched/core.c:3878
Âschedule+0xa8/0x270 kernel/sched/core.c:3942
Ârwsem_down_write_slowpath+0x70a/0xf70 kernel/locking/rwsem.c:1198
Â__down_write kernel/locking/rwsem.c:1349 [inline]
Âdown_write+0x13c/0x150 kernel/locking/rwsem.c:1485
Âunregister_netdevice_notifier+0x7e/0x390 net/core/dev.c:1713
Âbcm_release+0x93/0x5e0 net/can/bcm.c:1525
Â__sock_release+0xce/0x280 net/socket.c:586
Âsock_close+0x1e/0x30 net/socket.c:1264
Â__fput+0x2ff/0x890 fs/file_table.c:280
Â____fput+0x16/0x20 fs/file_table.c:313
Âtask_work_run+0x145/0x1c0 kernel/task_work.c:113
Âtracehook_notify_resume include/linux/tracehook.h:185 [inline]
Âexit_to_usermode_loop+0x316/0x380 arch/x86/entry/common.c:163
Âprepare_exit_to_usermode arch/x86/entry/common.c:194 [inline]
Âsyscall_return_slowpath arch/x86/entry/common.c:274 [inline]
Âdo_syscall_64+0x5a9/0x6a0 arch/x86/entry/common.c:299
Âentry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x413501
Code: 75 14 b8 03 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 04 1b 00 00 c3 48 83 ec 08 e8 0a fc ff ff 48 89 04 24 b8 03 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 53 fc ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:0000000000a6fbc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000413501
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
RBP: 0000000000000001 R08: ffffffffffffffff R09: ffffffffffffffff
R10: 0000000000a6fca0 R11: 0000000000000293 R12: 000000000075c9a0
R13: 000000000075c9a0 R14: 00000000007619c8 R15: ffffffffffffffff
INFO: task syz-executor.5:9533 blocked for more than 148 seconds.
ÂÂÂÂÂ Not tainted 5.2.0+ #80
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.5Â D28136Â 9533ÂÂ 9358 0x00000004
Call Trace:
Âcontext_switch kernel/sched/core.c:3252 [inline]
Â__schedule+0x755/0x1580 kernel/sched/core.c:3878
Âschedule+0xa8/0x270 kernel/sched/core.c:3942
Ârwsem_down_write_slowpath+0x70a/0xf70 kernel/locking/rwsem.c:1198
Â__down_write kernel/locking/rwsem.c:1349 [inline]
Âdown_write+0x13c/0x150 kernel/locking/rwsem.c:1485
Âunregister_netdevice_notifier+0x7e/0x390 net/core/dev.c:1713
Âbcm_release+0x93/0x5e0 net/can/bcm.c:1525
Â__sock_release+0xce/0x280 net/socket.c:586
Âsock_close+0x1e/0x30 net/socket.c:1264
Â__fput+0x2ff/0x890 fs/file_table.c:280
Â____fput+0x16/0x20 fs/file_table.c:313
Âtask_work_run+0x145/0x1c0 kernel/task_work.c:113
Âtracehook_notify_resume include/linux/tracehook.h:185 [inline]
Âexit_to_usermode_loop+0x316/0x380 arch/x86/entry/common.c:163
Âprepare_exit_to_usermode arch/x86/entry/common.c:194 [inline]
Âsyscall_return_slowpath arch/x86/entry/common.c:274 [inline]
Âdo_syscall_64+0x5a9/0x6a0 arch/x86/entry/common.c:299
Âentry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x413501
Code: 5f fe ff ff 31 c9 31 f6 41 b9 b0 20 41 00 41 b8 8c d6 65 00 ba 02 00 00 00 bf 28 38 44 00 ff 15 7d a1 24 00 85 c0 0f 85 37 fe <ff> ff 31 c9 31 f6 41 b9 b0 20 41 00 41 b8 90 d6 65 00 ba 03 00 00
RSP: 002b:0000000000a6fbc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000413501
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
RBP: 0000000000000001 R08: ffffffffffffffff R09: ffffffffffffffff
R10: 0000000000a6fca0 R11: 0000000000000293 R12: 000000000075c9a0
R13: 000000000075c9a0 R14: 00000000007619c8 R15: ffffffffffffffff
INFO: task syz-executor.1:9534 blocked for more than 148 seconds.
ÂÂÂÂÂ Not tainted 5.2.0+ #80
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.1Â D28136Â 9534ÂÂ 9359 0x00000004
Call Trace:
Âcontext_switch kernel/sched/core.c:3252 [inline]
Â__schedule+0x755/0x1580 kernel/sched/core.c:3878
Âschedule+0xa8/0x270 kernel/sched/core.c:3942
Ârwsem_down_write_slowpath+0x70a/0xf70 kernel/locking/rwsem.c:1198
Â__down_write kernel/locking/rwsem.c:1349 [inline]
Âdown_write+0x13c/0x150 kernel/locking/rwsem.c:1485
Âunregister_netdevice_notifier+0x7e/0x390 net/core/dev.c:1713
Âbcm_release+0x93/0x5e0 net/can/bcm.c:1525
Â__sock_release+0xce/0x280 net/socket.c:586
Âsock_close+0x1e/0x30 net/socket.c:1264
Â__fput+0x2ff/0x890 fs/file_table.c:280
Â____fput+0x16/0x20 fs/file_table.c:313
Âtask_work_run+0x145/0x1c0 kernel/task_work.c:113
Âtracehook_notify_resume include/linux/tracehook.h:185 [inline]
Âexit_to_usermode_loop+0x316/0x380 arch/x86/entry/common.c:163
Âprepare_exit_to_usermode arch/x86/entry/common.c:194 [inline]
Âsyscall_return_slowpath arch/x86/entry/common.c:274 [inline]
Âdo_syscall_64+0x5a9/0x6a0 arch/x86/entry/common.c:299
Âentry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x413501
Code: 75 14 b8 03 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 04 1b 00 00 c3 48 83 ec 08 e8 0a fc ff ff 48 89 04 24 b8 03 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 53 fc ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:0000000000a6fbc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000413501
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
RBP: 0000000000000001 R08: ffffffffffffffff R09: ffffffffffffffff
R10: 0000000000a6fca0 R11: 0000000000000293 R12: 000000000075c9a0
R13: 000000000075c9a0 R14: 00000000007619c8 R15: ffffffffffffffff
INFO: task syz-executor.3:9535 blocked for more than 150 seconds.
ÂÂÂÂÂ Not tainted 5.2.0+ #80
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.3Â D28136Â 9535ÂÂ 9351 0x00000004
Call Trace:
Âcontext_switch kernel/sched/core.c:3252 [inline]
Â__schedule+0x755/0x1580 kernel/sched/core.c:3878
Âschedule+0xa8/0x270 kernel/sched/core.c:3942
Ârwsem_down_write_slowpath+0x70a/0xf70 kernel/locking/rwsem.c:1198
Â__down_write kernel/locking/rwsem.c:1349 [inline]
Âdown_write+0x13c/0x150 kernel/locking/rwsem.c:1485
Âunregister_netdevice_notifier+0x7e/0x390 net/core/dev.c:1713
Âbcm_release+0x93/0x5e0 net/can/bcm.c:1525
Â__sock_release+0xce/0x280 net/socket.c:586
Âsock_close+0x1e/0x30 net/socket.c:1264
Â__fput+0x2ff/0x890 fs/file_table.c:280
Â____fput+0x16/0x20 fs/file_table.c:313
Âtask_work_run+0x145/0x1c0 kernel/task_work.c:113
Âtracehook_notify_resume include/linux/tracehook.h:185 [inline]
Âexit_to_usermode_loop+0x316/0x380 arch/x86/entry/common.c:163
Âprepare_exit_to_usermode arch/x86/entry/common.c:194 [inline]
Âsyscall_return_slowpath arch/x86/entry/common.c:274 [inline]
Âdo_syscall_64+0x5a9/0x6a0 arch/x86/entry/common.c:299
Âentry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x413501
Code: 75 14 b8 03 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 04 1b 00 00 c3 48 83 ec 08 e8 0a fc ff ff 48 89 04 24 b8 03 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 53 fc ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:0000000000a6fbc0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000413501
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
RBP: 0000000000000001 R08: ffffffffffffffff R09: ffffffffffffffff
R10: 0000000000a6fca0 R11: 0000000000000293 R12: 000000000075c9a0
R13: 000000000075c9a0 R14: 00000000007619c8 R15: ffffffffffffffff

Showing all locks held in the system:
1 lock held by khungtaskd/1049:
Â#0: 00000000ede263b0 (rcu_read_lock){....}, at: debug_show_all_locks+0x5f/0x27e kernel/locking/lockdep.c:5257
1 lock held by rsyslogd/9208:
Â#0: 00000000da20b59a (&f->f_pos_lock){+.+.}, at: __fdget_pos+0xee/0x110 fs/file.c:801
2 locks held by getty/9298:
Â#0: 00000000e9efae0d (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:341
Â#1: 0000000007287a12 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x232/0x1c10 drivers/tty/n_tty.c:2156
2 locks held by getty/9299:
Â#0: 00000000ad0733b0 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:341
Â#1: 0000000094dd5193 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x232/0x1c10 drivers/tty/n_tty.c:2156
2 locks held by getty/9300:
Â#0: 00000000692c340f (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:341
Â#1: 00000000538c7d7d (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x232/0x1c10 drivers/tty/n_tty.c:2156
2 locks held by getty/9301:
Â#0: 00000000116ea6c7 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:341
Â#1: 00000000a908a9f7 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x232/0x1c10 drivers/tty/n_tty.c:2156
2 locks held by getty/9302:
Â#0: 0000000042704f01 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:341
Â#1: 0000000041cc8671 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x232/0x1c10 drivers/tty/n_tty.c:2156
2 locks held by getty/9303:
Â#0: 000000001ef3b293 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:341
Â#1: 000000008b703302 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x232/0x1c10 drivers/tty/n_tty.c:2156
2 locks held by getty/9304:
Â#0: 0000000095601bb0 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x33/0x40 drivers/tty/tty_ldsem.c:341