Hello Johannes,
If you have time, could you please take a look at this? I do not have any
quick or reliable way to reproduce this, but since one of the threads is blocked
on a debugfs completion, then I'm suspicious it may be some other bug in the area
you previously (mostly?) fixed.
Maybe because the kworkers are blocked on ipv6 stuff so whatever completion
work we are waiting on will never complete?
gdb) l *(wiphy_locked_debugfs_read+0x114)
0x713e4 is in wiphy_locked_debugfs_read (/home/greearb/git/linux-6.7.dev.y/net/wireless/debugfs.c:182).
177 wiphy_work_init(&work.work, wiphy_locked_debugfs_read_work);
178 wiphy_work_queue(wiphy, &work.work);
179
180 debugfs_enter_cancellation(file, &cancellation);
181 wait_for_completion(&work.completion);
182 debugfs_leave_cancellation(file, &cancellation);
183
184 if (work.ret < 0)
185 return work.ret;
186
(gdb)
[905261.271981] INFO: task systemd-resolve:948 blocked for more than 180 seconds.
[905261.277834] Tainted: G O 6.7.3+ #34
[905261.281939] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.288474] task:systemd-resolve state:D stack:0 pid:948 tgid:948 ppid:1 flags:0x00000002
[905261.288477] Call Trace:
[905261.288478] <TASK>
[905261.288481] __schedule+0x377/0xa10
[905261.288486] ? _copy_to_user+0x20/0x30
[905261.288507] schedule+0x29/0xc0
[905261.288509] schedule_preempt_disabled+0xc/0x20
[905261.288511] __mutex_lock.constprop.0+0x34d/0x760
[905261.288514] do_ip_setsockopt+0x4a/0x1150
[905261.288518] ? ___sys_recvmsg+0x82/0xc0
[905261.288520] ip_setsockopt+0x2a/0xb0
[905261.288523] do_sock_setsockopt+0xa8/0x170
[905261.288527] __sys_setsockopt+0x85/0xd0
[905261.288529] __x64_sys_setsockopt+0x16/0x20
[905261.288530] do_syscall_64+0x3b/0x110
[905261.288533] entry_SYSCALL_64_after_hwframe+0x46/0x4e
[905261.288537] RIP: 0033:0x7f228251389e
[905261.288539] RSP: 002b:00007ffd4466fd38 EFLAGS: 00000246 ORIG_RAX: 0000000000000036
[905261.288541] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f228251389e
[905261.288542] RDX: 0000000000000024 RSI: 0000000000000000 RDI: 000000000000000a
[905261.288543] RBP: 000000000000000a R08: 000000000000000c R09: 8e92374df5b14b7b
[905261.288544] R10: 00007ffd4466fd44 R11: 0000000000000246 R12: 00007ffd4466fd44
[905261.288546] R13: 0000000000000000 R14: 0000561411a0ae00 R15: 0000561411a0ae00
[905261.288548] </TASK>
[905261.288556] INFO: task ntpd:1435 blocked for more than 180 seconds.
[905261.293524] Tainted: G O 6.7.3+ #34
[905261.297632] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.304168] task:ntpd state:D stack:0 pid:1435 tgid:1435 ppid:1 flags:0x00000006
[905261.304170] Call Trace:
[905261.304171] <TASK>
[905261.304172] __schedule+0x377/0xa10
[905261.304174] schedule+0x29/0xc0
[905261.304175] schedule_preempt_disabled+0xc/0x20
[905261.304177] __mutex_lock.constprop.0+0x34d/0x760
[905261.304179] __netlink_dump_start+0x6c/0x280
[905261.304196] ? rtnl_fill_ifinfo+0x1510/0x1510
[905261.304198] rtnetlink_rcv_msg+0x267/0x3b0
[905261.304202] ? rtnl_fill_ifinfo+0x1510/0x1510
[905261.304203] ? rtnl_calcit.isra.0+0x120/0x120
[905261.304205] netlink_rcv_skb+0x4f/0x100
[905261.304207] netlink_unicast+0x18b/0x280
[905261.304209] netlink_sendmsg+0x24b/0x4c0
[905261.304211] __sock_sendmsg+0x33/0x60
[905261.304212] __sys_sendto+0xec/0x130
[905261.304214] ? __sys_socket+0xc1/0xf0
[905261.304216] __x64_sys_sendto+0x1b/0x20
[905261.304217] do_syscall_64+0x3b/0x110
[905261.304218] entry_SYSCALL_64_after_hwframe+0x46/0x4e
[905261.304221] RIP: 0033:0x7f438bb13834
[905261.304222] RSP: 002b:00007fff186e10f0 EFLAGS: 00000293 ORIG_RAX: 000000000000002c
[905261.304223] RAX: ffffffffffffffda RBX: 00007fff186e2180 RCX: 00007f438bb13834
[905261.304225] RDX: 0000000000000014 RSI: 00007fff186e21c0 RDI: 0000000000000004
[905261.304225] RBP: 0000000000000000 R08: 00007fff186e2180 R09: 000000000000000c
[905261.304226] R10: 0000000000000000 R11: 0000000000000293 R12: 00007fff186e21c0
[905261.304227] R13: 000055fd78123140 R14: 00007fff186e1130 R15: 00007fff186e2280
[905261.304229] </TASK>
[905261.304239] INFO: task abrt-applet:2433 blocked for more than 180 seconds.
[905261.309820] Tainted: G O 6.7.3+ #34
[905261.313926] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.320462] task:abrt-applet state:D stack:0 pid:2433 tgid:2433 ppid:2046 flags:0x00000002
[905261.320465] Call Trace:
[905261.320466] <TASK>
[905261.320467] __schedule+0x377/0xa10
[905261.320469] ? poll_freewait+0x40/0xa0
[905261.320472] schedule+0x29/0xc0
[905261.320487] schedule_preempt_disabled+0xc/0x20
[905261.320489] __mutex_lock.constprop.0+0x34d/0x760
[905261.320492] __netlink_dump_start+0x6c/0x280
[905261.320494] ? rtnl_mdb_dump+0x160/0x160
[905261.320497] rtnetlink_rcv_msg+0x267/0x3b0
[905261.320499] ? rtnl_mdb_dump+0x160/0x160
[905261.320501] ? rtnl_calcit.isra.0+0x120/0x120
[905261.320504] netlink_rcv_skb+0x4f/0x100
[905261.320506] netlink_unicast+0x18b/0x280
[905261.320507] netlink_sendmsg+0x24b/0x4c0
[905261.320509] __sock_sendmsg+0x33/0x60
[905261.320510] ? sockfd_lookup_light+0xd/0x60
[905261.320513] __sys_sendto+0xec/0x130
[905261.320515] ? eventfd_read+0xc9/0x200
[905261.320517] ? eventfd_write+0xc0/0x1d0
[905261.320519] ? ktime_get_ts64+0x44/0xe0
[905261.320523] ? switch_fpu_return+0x47/0xc0
[905261.320526] __x64_sys_sendto+0x1b/0x20
[905261.320527] do_syscall_64+0x3b/0x110
[905261.320529] entry_SYSCALL_64_after_hwframe+0x46/0x4e
[905261.320532] RIP: 0033:0x7f01c15136cc
[905261.320533] RSP: 002b:00007fff04b4a210 EFLAGS: 00000246 ORIG_RAX: 000000000000002c
[905261.320535] RAX: ffffffffffffffda RBX: 000055b502c7f3d0 RCX: 00007f01c15136cc
[905261.320536] RDX: 0000000000000014 RSI: 00007fff04b4a290 RDI: 0000000000000003
[905261.320537] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[905261.320538] R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000014
[905261.320539] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[905261.320540] </TASK>
[905261.320542] INFO: task xdg-desktop-por:2485 blocked for more than 180 seconds.
[905261.326467] Tainted: G O 6.7.3+ #34
[905261.330577] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.337114] task:xdg-desktop-por state:D stack:0 pid:2485 tgid:2485 ppid:1742 flags:0x00000002
[905261.337116] Call Trace:
[905261.337117] <TASK>
[905261.337118] __schedule+0x377/0xa10
[905261.337120] ? poll_freewait+0x40/0xa0
[905261.337122] schedule+0x29/0xc0
[905261.337138] schedule_preempt_disabled+0xc/0x20
[905261.337139] __mutex_lock.constprop.0+0x34d/0x760
[905261.337142] __netlink_dump_start+0x6c/0x280
[905261.337143] ? rtnl_mdb_dump+0x160/0x160
[905261.337146] rtnetlink_rcv_msg+0x267/0x3b0
[905261.337148] ? rtnl_mdb_dump+0x160/0x160
[905261.337150] ? rtnl_calcit.isra.0+0x120/0x120
[905261.337153] netlink_rcv_skb+0x4f/0x100
[905261.337155] netlink_unicast+0x18b/0x280
[905261.337156] netlink_sendmsg+0x24b/0x4c0
[905261.337158] __sock_sendmsg+0x33/0x60
[905261.337159] ? sockfd_lookup_light+0xd/0x60
[905261.337162] __sys_sendto+0xec/0x130
[905261.337163] ? eventfd_read+0xc9/0x200
[905261.337165] ? eventfd_write+0xc0/0x1d0
[905261.337167] ? ktime_get_ts64+0x44/0xe0
[905261.337170] ? switch_fpu_return+0x47/0xc0
[905261.337172] __x64_sys_sendto+0x1b/0x20
[905261.337173] do_syscall_64+0x3b/0x110
[905261.337174] entry_SYSCALL_64_after_hwframe+0x46/0x4e
[905261.337178] RIP: 0033:0x7f21443136cc
[905261.337179] RSP: 002b:00007ffc9a315160 EFLAGS: 00000246 ORIG_RAX: 000000000000002c
[905261.337180] RAX: ffffffffffffffda RBX: 0000561a0dfc43d0 RCX: 00007f21443136cc
[905261.337181] RDX: 0000000000000014 RSI: 00007ffc9a3151e0 RDI: 0000000000000008
[905261.337182] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[905261.337183] R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000014
[905261.337184] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[905261.337185] </TASK>
[905261.337190] INFO: task gnuserver:3266 blocked for more than 180 seconds.
[905261.342597] Tainted: G O 6.7.3+ #34
[905261.346705] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.353238] task:gnuserver state:D stack:0 pid:3266 tgid:3266 ppid:3218 flags:0x00000002
[905261.353240] Call Trace:
[905261.353241] <TASK>
[905261.353241] __schedule+0x377/0xa10
[905261.353243] schedule+0x29/0xc0
[905261.353245] schedule_preempt_disabled+0xc/0x20
[905261.353247] __mutex_lock.constprop.0+0x34d/0x760
[905261.353249] dev_ethtool+0x9e/0x29a0
[905261.353267] ? atime_needs_update+0x93/0x110
[905261.353270] ? touch_atime+0x15/0x110
[905261.353273] ? filemap_read+0x2e2/0x300
[905261.353277] dev_ioctl+0x256/0x480
[905261.353280] sock_do_ioctl+0x8e/0xd0
[905261.353281] sock_ioctl+0x157/0x2a0
[905261.353283] __x64_sys_ioctl+0x87/0xc0
[905261.353285] do_syscall_64+0x3b/0x110
[905261.353287] entry_SYSCALL_64_after_hwframe+0x46/0x4e
[905261.353289] RIP: 0033:0x7f40e5b0774f
[905261.353290] RSP: 002b:00007fffca032a30 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[905261.353291] RAX: ffffffffffffffda RBX: 00007fffca032b10 RCX: 00007f40e5b0774f
[905261.353292] RDX: 00007fffca033190 RSI: 0000000000008946 RDI: 0000000000000008
[905261.353293] RBP: 00007fffca033190 R08: 000000000000000a R09: 00224f4e223d4c54
[905261.353294] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000008
[905261.353295] R13: 0000000000000008 R14: 00007fffca033240 R15: 0000000000000000
[905261.353297] </TASK>
[905261.353300] INFO: task btserver:3593 blocked for more than 180 seconds.
[905261.358620] Tainted: G O 6.7.3+ #34
[905261.362729] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.369263] task:btserver state:D stack:0 pid:3593 tgid:3593 ppid:2866 flags:0x00000002
[905261.369265] Call Trace:
[905261.369266] <TASK>
[905261.369267] __schedule+0x377/0xa10
[905261.369268] ? sched_clock+0xc/0x20
[905261.369270] schedule+0x29/0xc0
[905261.369271] schedule_timeout+0x136/0x150
[905261.369274] wait_for_completion+0x7d/0x130
[905261.369292] wiphy_locked_debugfs_read+0x114/0x180 [cfg80211]
[905261.369363] ? wiphy_locked_debugfs_write_work+0x30/0x30 [cfg80211]
[905261.369400] ? rts_threshold_read+0x80/0x80 [cfg80211]
[905261.369438] ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
[905261.369516] ieee80211_if_read_sdata+0x55/0x80 [mac80211]
[905261.369553] ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
[905261.369587] ? ieee80211_if_fmt_dot11MeshMaxRetries+0x20/0x20 [mac80211]
[905261.369621] full_proxy_read+0x4e/0x70
[905261.369625] vfs_read+0xa3/0x2c0
[905261.369628] ksys_read+0x5e/0xe0
[905261.369630] do_syscall_64+0x3b/0x110
[905261.369631] entry_SYSCALL_64_after_hwframe+0x46/0x4e
[905261.369633] RIP: 0033:0x7f27db101b92
[905261.369634] RSP: 002b:00007ffffe00d918 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[905261.369636] RAX: ffffffffffffffda RBX: 00007ffffe00da20 RCX: 00007f27db101b92
[905261.369637] RDX: 0000000000001fff RSI: 0000000009dae8f0 RDI: 0000000000000012
[905261.369638] RBP: 0000000000001fff R08: 0000000000002000 R09: 0000000000000000
[905261.369639] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000009dae8f0
[905261.369640] R13: 00007ffffe00da88 R14: 0000000003971712 R15: 0000000000000001
[905261.369641] </TASK>
[905261.369667] INFO: task kworker/6:1:2567676 blocked for more than 180 seconds.
[905261.375519] Tainted: G O 6.7.3+ #34
[905261.379656] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.386240] task:kworker/6:1 state:D stack:0 pid:2567676 tgid:2567676 ppid:2 flags:0x00004000
[905261.386243] Workqueue: ipv6_addrconf addrconf_dad_work
[905261.386247] Call Trace:
[905261.386248] <TASK>
[905261.386249] __schedule+0x377/0xa10
[905261.386251] ? ttwu_do_activate+0x58/0x1d0
[905261.386255] schedule+0x29/0xc0
[905261.386269] schedule_preempt_disabled+0xc/0x20
[905261.386270] __mutex_lock.constprop.0+0x34d/0x760
[905261.386273] addrconf_dad_work+0x39/0x590
[905261.386275] ? __schedule+0x37f/0xa10
[905261.386276] process_one_work+0x15d/0x330
[905261.386291] worker_thread+0x2e8/0x400
[905261.386293] ? rescuer_thread+0x400/0x400
[905261.386294] kthread+0xdc/0x110
[905261.386298] ? kthread_complete_and_exit+0x20/0x20
[905261.386300] ret_from_fork+0x28/0x40
[905261.386302] ? kthread_complete_and_exit+0x20/0x20
[905261.386310] ret_from_fork_asm+0x11/0x20
[905261.386315] </TASK>
[905261.386317] INFO: task kworker/7:1:2579027 blocked for more than 180 seconds.
[905261.392164] Tainted: G O 6.7.3+ #34
[905261.396313] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.402878] task:kworker/7:1 state:D stack:0 pid:2579027 tgid:2579027 ppid:2 flags:0x00004000
[905261.402881] Workqueue: ipv6_addrconf addrconf_dad_work
[905261.402884] Call Trace:
[905261.402884] <TASK>
[905261.402885] __schedule+0x377/0xa10
[905261.402887] schedule+0x29/0xc0
[905261.402889] schedule_preempt_disabled+0xc/0x20
[905261.402891] __mutex_lock.constprop.0+0x34d/0x760
[905261.402893] addrconf_dad_work+0x39/0x590
[905261.402895] ? __schedule+0x37f/0xa10
[905261.402896] process_one_work+0x15d/0x330
[905261.402898] worker_thread+0x2e8/0x400
[905261.402906] ? rescuer_thread+0x400/0x400
[905261.402908] kthread+0xdc/0x110
[905261.402911] ? kthread_complete_and_exit+0x20/0x20
[905261.402913] ret_from_fork+0x28/0x40
[905261.402915] ? kthread_complete_and_exit+0x20/0x20
[905261.402917] ret_from_fork_asm+0x11/0x20
[905261.402920] </TASK>
[905261.402921] INFO: task kworker/u16:17:2582370 blocked for more than 180 seconds.
[905261.409024] Tainted: G O 6.7.3+ #34
[905261.413157] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.419735] task:kworker/u16:17 state:D stack:0 pid:2582370 tgid:2582370 ppid:2 flags:0x00004000
[905261.419738] Workqueue: events_unbound cfg80211_wiphy_work [cfg80211]
[905261.419788] Call Trace:
[905261.419788] <TASK>
[905261.419789] __schedule+0x377/0xa10
[905261.419792] schedule+0x29/0xc0
[905261.419793] schedule_preempt_disabled+0xc/0x20
[905261.419795] __mutex_lock.constprop.0+0x34d/0x760
[905261.419797] cfg80211_wiphy_work+0x15/0xb0 [cfg80211]
[905261.419827] process_one_work+0x15d/0x330
[905261.419829] worker_thread+0x2e8/0x400
[905261.419831] ? rescuer_thread+0x400/0x400
[905261.419832] kthread+0xdc/0x110
[905261.419834] ? kthread_complete_and_exit+0x20/0x20
[905261.419854] ret_from_fork+0x28/0x40
[905261.419856] ? kthread_complete_and_exit+0x20/0x20
[905261.419859] ret_from_fork_asm+0x11/0x20
[905261.419862] </TASK>
[905261.419864] INFO: task kworker/0:1:2591382 blocked for more than 180 seconds.
[905261.425716] Tainted: G O 6.7.3+ #34
[905261.429854] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[905261.436399] task:kworker/0:1 state:D stack:0 pid:2591382 tgid:2591382 ppid:2 flags:0x00004000
[905261.436403] Workqueue: ipv6_addrconf addrconf_dad_work
[905261.436406] Call Trace:
[905261.436421] <TASK>
[905261.436422] __schedule+0x377/0xa10
[905261.436424] schedule+0x29/0xc0
[905261.436425] schedule_preempt_disabled+0xc/0x20
[905261.436427] __mutex_lock.constprop.0+0x34d/0x760
[905261.436429] addrconf_dad_work+0x39/0x590
[905261.436431] ? __schedule+0x37f/0xa10
[905261.436433] process_one_work+0x15d/0x330
[905261.436435] worker_thread+0x2e8/0x400
[905261.436436] ? rescuer_thread+0x400/0x400
[905261.436437] kthread+0xdc/0x110
[905261.436440] ? kthread_complete_and_exit+0x20/0x20
[905261.436442] ret_from_fork+0x28/0x40
[905261.436443] ? kthread_complete_and_exit+0x20/0x20
[905261.436446] ret_from_fork_asm+0x11/0x20
[905261.436448] </TASK>
[905261.436449] Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings
Thanks,
Ben
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
On Fri, 2024-02-23 at 09:08 -0800, Ben Greear wrote:
> [905261.271981] INFO: task systemd-resolve:948 blocked for more than 180 seconds.
> [905261.277834] Tainted: G O 6.7.3+ #34
> [905261.281939] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [905261.288474] task:systemd-resolve state:D stack:0 pid:948 tgid:948 ppid:1 flags:0x00000002
I don't know what that's doing, but
> [905261.288477] Call Trace:
> [905261.288478] <TASK>
> [905261.288481] __schedule+0x377/0xa10
> [905261.288486] ? _copy_to_user+0x20/0x30
> [905261.288507] schedule+0x29/0xc0
> [905261.288509] schedule_preempt_disabled+0xc/0x20
> [905261.288511] __mutex_lock.constprop.0+0x34d/0x760
> [905261.288514] do_ip_setsockopt+0x4a/0x1150
I'm going to assume that this is RTNL, the socket lock isn't technically
a mutex, and doesn't seem reasonable in this context.
> [905261.337114] task:xdg-desktop-por state:D stack:0 pid:2485 tgid:2485 ppid:1742 flags:0x00000002
> [905261.337116] Call Trace:
> [905261.337117] <TASK>
> [905261.337118] __schedule+0x377/0xa10
> [905261.337120] ? poll_freewait+0x40/0xa0
> [905261.337122] schedule+0x29/0xc0
> [905261.337138] schedule_preempt_disabled+0xc/0x20
> [905261.337139] __mutex_lock.constprop.0+0x34d/0x760
> [905261.337142] __netlink_dump_start+0x6c/0x280
> [905261.337143] ? rtnl_mdb_dump+0x160/0x160
> [905261.337146] rtnetlink_rcv_msg+0x267/0x3b0
A lot of other things are waiting for the RTNL too.
> [905261.353300] INFO: task btserver:3593 blocked for more than 180 seconds.
> [905261.358620] Tainted: G O 6.7.3+ #34
> [905261.362729] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [905261.369263] task:btserver state:D stack:0 pid:3593 tgid:3593 ppid:2866 flags:0x00000002
> [905261.369265] Call Trace:
> [905261.369266] <TASK>
> [905261.369267] __schedule+0x377/0xa10
> [905261.369268] ? sched_clock+0xc/0x20
> [905261.369270] schedule+0x29/0xc0
> [905261.369271] schedule_timeout+0x136/0x150
> [905261.369274] wait_for_completion+0x7d/0x130
> [905261.369292] wiphy_locked_debugfs_read+0x114/0x180 [cfg80211]
> [905261.369363] ? wiphy_locked_debugfs_write_work+0x30/0x30 [cfg80211]
> [905261.369400] ? rts_threshold_read+0x80/0x80 [cfg80211]
> [905261.369438] ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
> [905261.369516] ieee80211_if_read_sdata+0x55/0x80 [mac80211]
This you saw - it's waiting for the completion of the read of the ...
not sure which file? Any chance you could find out which fd this process
has open when it happens?
> [905261.369553] ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
> [905261.369587] ? ieee80211_if_fmt_dot11MeshMaxRetries+0x20/0x20 [mac80211]
I don't think we can trust any of the lines marked "?", they're probably
old prior stack contents ... these don't show up in the call stack of
ieee80211_if_read_sdata() directly, after all.
> [905261.402921] INFO: task kworker/u16:17:2582370 blocked for more than 180 seconds.
> [905261.409024] Tainted: G O 6.7.3+ #34
> [905261.413157] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [905261.419735] task:kworker/u16:17 state:D stack:0 pid:2582370 tgid:2582370 ppid:2 flags:0x00004000
> [905261.419738] Workqueue: events_unbound cfg80211_wiphy_work [cfg80211]
> [905261.419788] Call Trace:
> [905261.419788] <TASK>
> [905261.419789] __schedule+0x377/0xa10
> [905261.419792] schedule+0x29/0xc0
> [905261.419793] schedule_preempt_disabled+0xc/0x20
> [905261.419795] __mutex_lock.constprop.0+0x34d/0x760
> [905261.419797] cfg80211_wiphy_work+0x15/0xb0 [cfg80211]
> [905261.419827] process_one_work+0x15d/0x330
This is a bit interesting - why is the wiphy work stuck trying to
acquire the wiphy mutex? But nothing related to the RTNL.
This does explain why the debugfs is stuck though. So maybe doesn't
matter knowing which file got stuck ...
> [905261.436449] Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings
I think we're missing the process that's actually stuck though, maybe
here or later?
Seems like there must be a process somewhere that holds RTNL and wiphy
mutex, but didn't get listed here. Maybe it's live-locked? Maybe it's
actually a netdev removal (which would hold both those locks), but then
why is it stuck and not shown?
johannes
On 2/26/24 00:42, Johannes Berg wrote:
> On Fri, 2024-02-23 at 09:08 -0800, Ben Greear wrote:
>
>> [905261.271981] INFO: task systemd-resolve:948 blocked for more than 180 seconds.
>> [905261.277834] Tainted: G O 6.7.3+ #34
>> [905261.281939] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [905261.288474] task:systemd-resolve state:D stack:0 pid:948 tgid:948 ppid:1 flags:0x00000002
>
> I don't know what that's doing, but
>
>> [905261.288477] Call Trace:
>> [905261.288478] <TASK>
>> [905261.288481] __schedule+0x377/0xa10
>> [905261.288486] ? _copy_to_user+0x20/0x30
>> [905261.288507] schedule+0x29/0xc0
>> [905261.288509] schedule_preempt_disabled+0xc/0x20
>> [905261.288511] __mutex_lock.constprop.0+0x34d/0x760
>> [905261.288514] do_ip_setsockopt+0x4a/0x1150
>
> I'm going to assume that this is RTNL, the socket lock isn't technically
> a mutex, and doesn't seem reasonable in this context.
>
>> [905261.337114] task:xdg-desktop-por state:D stack:0 pid:2485 tgid:2485 ppid:1742 flags:0x00000002
>> [905261.337116] Call Trace:
>> [905261.337117] <TASK>
>> [905261.337118] __schedule+0x377/0xa10
>> [905261.337120] ? poll_freewait+0x40/0xa0
>> [905261.337122] schedule+0x29/0xc0
>> [905261.337138] schedule_preempt_disabled+0xc/0x20
>> [905261.337139] __mutex_lock.constprop.0+0x34d/0x760
>> [905261.337142] __netlink_dump_start+0x6c/0x280
>> [905261.337143] ? rtnl_mdb_dump+0x160/0x160
>> [905261.337146] rtnetlink_rcv_msg+0x267/0x3b0
>
> A lot of other things are waiting for the RTNL too.
>
>> [905261.353300] INFO: task btserver:3593 blocked for more than 180 seconds.
>> [905261.358620] Tainted: G O 6.7.3+ #34
>> [905261.362729] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [905261.369263] task:btserver state:D stack:0 pid:3593 tgid:3593 ppid:2866 flags:0x00000002
>> [905261.369265] Call Trace:
>> [905261.369266] <TASK>
>> [905261.369267] __schedule+0x377/0xa10
>> [905261.369268] ? sched_clock+0xc/0x20
>> [905261.369270] schedule+0x29/0xc0
>> [905261.369271] schedule_timeout+0x136/0x150
>> [905261.369274] wait_for_completion+0x7d/0x130
>> [905261.369292] wiphy_locked_debugfs_read+0x114/0x180 [cfg80211]
>> [905261.369363] ? wiphy_locked_debugfs_write_work+0x30/0x30 [cfg80211]
>> [905261.369400] ? rts_threshold_read+0x80/0x80 [cfg80211]
>> [905261.369438] ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
>> [905261.369516] ieee80211_if_read_sdata+0x55/0x80 [mac80211]
>
> This you saw - it's waiting for the completion of the read of the ...
> not sure which file? Any chance you could find out which fd this process
> has open when it happens?
>
>> [905261.369553] ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
>> [905261.369587] ? ieee80211_if_fmt_dot11MeshMaxRetries+0x20/0x20 [mac80211]
>
> I don't think we can trust any of the lines marked "?", they're probably
> old prior stack contents ... these don't show up in the call stack of
> ieee80211_if_read_sdata() directly, after all.
>
>> [905261.402921] INFO: task kworker/u16:17:2582370 blocked for more than 180 seconds.
>> [905261.409024] Tainted: G O 6.7.3+ #34
>> [905261.413157] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [905261.419735] task:kworker/u16:17 state:D stack:0 pid:2582370 tgid:2582370 ppid:2 flags:0x00004000
>> [905261.419738] Workqueue: events_unbound cfg80211_wiphy_work [cfg80211]
>> [905261.419788] Call Trace:
>> [905261.419788] <TASK>
>> [905261.419789] __schedule+0x377/0xa10
>> [905261.419792] schedule+0x29/0xc0
>> [905261.419793] schedule_preempt_disabled+0xc/0x20
>> [905261.419795] __mutex_lock.constprop.0+0x34d/0x760
>> [905261.419797] cfg80211_wiphy_work+0x15/0xb0 [cfg80211]
>> [905261.419827] process_one_work+0x15d/0x330
>
> This is a bit interesting - why is the wiphy work stuck trying to
> acquire the wiphy mutex? But nothing related to the RTNL.
>
> This does explain why the debugfs is stuck though. So maybe doesn't
> matter knowing which file got stuck ...
>
>> [905261.436449] Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings
>
> I think we're missing the process that's actually stuck though, maybe
> here or later?
>
> Seems like there must be a process somewhere that holds RTNL and wiphy
> mutex, but didn't get listed here. Maybe it's live-locked? Maybe it's
> actually a netdev removal (which would hold both those locks), but then
> why is it stuck and not shown?
I managed to catch it in a lockdep enabled kernel. There were no lockdep
warnings, but more lock info was printed at least:
Maybe ordering of this one's lock printout means it is 'ip' that is actually holding the rtnl?
[Seen in context further below]
Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by ip/28125:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: rtnetlink_rcv_msg+0x13e/0x620
Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: ieee80211_stop+0x2d/0x180 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffff88812661d768 (&sb->s_type->i_mutex_key#3){++++}-{4:4}, at: simple_recursive_removal+0x189/0x2b0
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task kworker/6:3:542 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:kworker/6:3 state:D stack:0 pid:542 tgid:542 ppid:2 flags:0x00004000
Feb 26 06:01:45 ct523c-0b0b kernel: Workqueue: ipv6_addrconf addrconf_verify_work
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_acquire+0xc6/0x2b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: process_one_work+0x1f6/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: worker_thread+0x1cc/0x3b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? wq_sysfs_prep_attrs+0x90/0x90
Feb 26 06:01:45 ct523c-0b0b kernel: kthread+0xec/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ret_from_fork+0x28/0x40
Feb 26 06:01:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ret_from_fork_asm+0x11/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task ntpd:1448 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:ntpd state:D stack:0 pid:1448 tgid:1448 ppid:1 flags:0x00000006
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:01:45 ct523c-0b0b kernel: ? netlink_lookup+0x13b/0x2f0
Feb 26 06:01:45 ct523c-0b0b kernel: ? __netlink_dump_start+0x7d/0x290
Feb 26 06:01:45 ct523c-0b0b kernel: ? __netlink_dump_start+0x7d/0x290
Feb 26 06:01:45 ct523c-0b0b kernel: __netlink_dump_start+0x7d/0x290
Feb 26 06:01:45 ct523c-0b0b kernel: ? rtnl_fill_ifinfo+0x1960/0x1960
Feb 26 06:01:45 ct523c-0b0b kernel: rtnetlink_rcv_msg+0x4d1/0x620
Feb 26 06:01:45 ct523c-0b0b kernel: ? rtnl_fill_ifinfo+0x1960/0x1960
Feb 26 06:01:45 ct523c-0b0b kernel: ? rtnl_getlink+0x3e0/0x3e0
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_rcv_skb+0x4f/0x100
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_unicast+0x18e/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_sendmsg+0x257/0x4d0
Feb 26 06:01:45 ct523c-0b0b kernel: __sock_sendmsg+0x33/0x60
Feb 26 06:01:45 ct523c-0b0b kernel: __sys_sendto+0xef/0x130
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: ? fd_install+0xb8/0x2e0
Feb 26 06:01:45 ct523c-0b0b kernel: ? __sys_socket+0xc1/0xf0
Feb 26 06:01:45 ct523c-0b0b kernel: __x64_sys_sendto+0x1b/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: do_syscall_64+0x3b/0x110
Feb 26 06:01:45 ct523c-0b0b kernel: entry_SYSCALL_64_after_hwframe+0x46/0x4e
Feb 26 06:01:45 ct523c-0b0b kernel: RIP: 0033:0x7f14ccd13834
Feb 26 06:01:45 ct523c-0b0b kernel: RSP: 002b:00007ffdaa403950 EFLAGS: 00000293 ORIG_RAX: 000000000000002c
Feb 26 06:01:45 ct523c-0b0b kernel: RAX: ffffffffffffffda RBX: 00007ffdaa4049e0 RCX: 00007f14ccd13834
Feb 26 06:01:45 ct523c-0b0b kernel: RDX: 0000000000000014 RSI: 00007ffdaa404a20 RDI: 0000000000000004
Feb 26 06:01:45 ct523c-0b0b kernel: RBP: 0000000000000000 R08: 00007ffdaa4049e0 R09: 000000000000000c
Feb 26 06:01:45 ct523c-0b0b kernel: R10: 0000000000000000 R11: 0000000000000293 R12: 00007ffdaa404a20
Feb 26 06:01:45 ct523c-0b0b kernel: R13: 000055a0c5771010 R14: 00007ffdaa403990 R15: 00007ffdaa404ae0
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task gnuserver:3271 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:gnuserver state:D stack:0 pid:3271 tgid:3271 ppid:3212 flags:0x00000002
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:01:45 ct523c-0b0b kernel: ? dev_ethtool+0x9e/0x29b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? dev_ethtool+0x9e/0x29b0
Feb 26 06:01:45 ct523c-0b0b kernel: dev_ethtool+0x9e/0x29b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_acquire+0xc6/0x2b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? dev_load+0x1c/0x140
Feb 26 06:01:45 ct523c-0b0b kernel: ? find_held_lock+0x2b/0x80
Feb 26 06:01:45 ct523c-0b0b kernel: ? dev_load+0x64/0x140
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: dev_ioctl+0x29d/0x510
Feb 26 06:01:45 ct523c-0b0b kernel: sock_do_ioctl+0x8e/0xd0
Feb 26 06:01:45 ct523c-0b0b kernel: ? find_held_lock+0x2b/0x80
Feb 26 06:01:45 ct523c-0b0b kernel: sock_ioctl+0x168/0x2e0
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: __x64_sys_ioctl+0x87/0xc0
Feb 26 06:01:45 ct523c-0b0b kernel: do_syscall_64+0x3b/0x110
Feb 26 06:01:45 ct523c-0b0b kernel: entry_SYSCALL_64_after_hwframe+0x46/0x4e
Feb 26 06:01:45 ct523c-0b0b kernel: RIP: 0033:0x7f3739b0774f
Feb 26 06:01:45 ct523c-0b0b kernel: RSP: 002b:00007ffc571e7140 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Feb 26 06:01:45 ct523c-0b0b kernel: RAX: ffffffffffffffda RBX: 00007ffc571e7220 RCX: 00007f3739b0774f
Feb 26 06:01:45 ct523c-0b0b kernel: RDX: 00007ffc571e78a0 RSI: 0000000000008946 RDI: 0000000000000008
Feb 26 06:01:45 ct523c-0b0b kernel: RBP: 00007ffc571e78a0 R08: 000000000000000a R09: 00224f4e223d4c54
Feb 26 06:01:45 ct523c-0b0b kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000008
Feb 26 06:01:45 ct523c-0b0b kernel: R13: 0000000000000008 R14: 00007ffc571e7950 R15: 0000000000000000
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task kworker/u16:1:8298 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:kworker/u16:1 state:D stack:0 pid:8298 tgid:8298 ppid:2 flags:0x00004000
Feb 26 06:01:45 ct523c-0b0b kernel: Workqueue: events_unbound cfg80211_wiphy_work [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:01:45 ct523c-0b0b kernel: ? cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: ? cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: process_one_work+0x1f6/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: worker_thread+0x1cc/0x3b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? wq_sysfs_prep_attrs+0x90/0x90
Feb 26 06:01:45 ct523c-0b0b kernel: kthread+0xec/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ret_from_fork+0x28/0x40
Feb 26 06:01:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ret_from_fork_asm+0x11/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task wpa_supplicant:26601 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:wpa_supplicant state:D stack:0 pid:26601 tgid:26601 ppid:1 flags:0x00000002
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:01:45 ct523c-0b0b kernel: ? __kmem_cache_alloc_node+0x4f/0x1e0
Feb 26 06:01:45 ct523c-0b0b kernel: ? genl_family_rcv_msg_attrs_parse.constprop.0+0x41/0xe0
Feb 26 06:01:45 ct523c-0b0b kernel: ? nl80211_pre_doit+0x1f/0x250 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? nl80211_pre_doit+0x1f/0x250 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: nl80211_pre_doit+0x1f/0x250 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: genl_family_rcv_msg_doit+0xc0/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: genl_rcv_msg+0x182/0x290
Feb 26 06:01:45 ct523c-0b0b kernel: ? __cfg80211_wdev_from_attrs+0x2b0/0x2b0 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? nl80211_set_sar_specs+0x3e0/0x3e0 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? nlmsg_trim+0x20/0x20 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? genl_family_rcv_msg_dumpit+0xf0/0xf0
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_rcv_skb+0x4f/0x100
Feb 26 06:01:45 ct523c-0b0b kernel: genl_rcv+0x1f/0x30
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_unicast+0x18e/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_sendmsg+0x257/0x4d0
Feb 26 06:01:45 ct523c-0b0b kernel: __sock_sendmsg+0x33/0x60
Feb 26 06:01:45 ct523c-0b0b kernel: ____sys_sendmsg+0x22c/0x2a0
Feb 26 06:01:45 ct523c-0b0b kernel: ? copy_msghdr_from_user+0x68/0xa0
Feb 26 06:01:45 ct523c-0b0b kernel: ___sys_sendmsg+0x81/0xc0
Feb 26 06:01:45 ct523c-0b0b kernel: ? find_held_lock+0x2b/0x80
Feb 26 06:01:45 ct523c-0b0b kernel: ? __might_fault+0x3c/0x70
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: ? _copy_from_user+0x4c/0x90
Feb 26 06:01:45 ct523c-0b0b kernel: ? netlink_setsockopt+0x248/0x350
Feb 26 06:01:45 ct523c-0b0b kernel: ? kfree+0xfc/0x130
Feb 26 06:01:45 ct523c-0b0b kernel: __sys_sendmsg+0x52/0xa0
Feb 26 06:01:45 ct523c-0b0b kernel: do_syscall_64+0x3b/0x110
Feb 26 06:01:45 ct523c-0b0b kernel: entry_SYSCALL_64_after_hwframe+0x46/0x4e
Feb 26 06:01:45 ct523c-0b0b kernel: RIP: 0033:0x7fe226313737
Feb 26 06:01:45 ct523c-0b0b kernel: RSP: 002b:00007fff50b8c6d8 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
Feb 26 06:01:45 ct523c-0b0b kernel: RAX: ffffffffffffffda RBX: 00000000009354e0 RCX: 00007fe226313737
Feb 26 06:01:45 ct523c-0b0b kernel: RDX: 0000000000000000 RSI: 00007fff50b8c730 RDI: 0000000000000007
Feb 26 06:01:45 ct523c-0b0b kernel: RBP: 0000000000a11ec0 R08: 0000000000000004 R09: 000000000000000d
Feb 26 06:01:45 ct523c-0b0b kernel: R10: 00007fff50b8c7fc R11: 0000000000000246 R12: 00000000009353f0
Feb 26 06:01:45 ct523c-0b0b kernel: R13: 00007fff50b8c730 R14: 00000000007a0d98 R15: 00007fe226cc1000
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task kworker/3:1:27514 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:kworker/3:1 state:D stack:0 pid:27514 tgid:27514 ppid:2 flags:0x00004000
Feb 26 06:01:45 ct523c-0b0b kernel: Workqueue: ipv6_addrconf addrconf_verify_work
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_acquire+0xc6/0x2b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: process_one_work+0x1f6/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: worker_thread+0x1cc/0x3b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? wq_sysfs_prep_attrs+0x90/0x90
Feb 26 06:01:45 ct523c-0b0b kernel: kthread+0xec/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ret_from_fork+0x28/0x40
Feb 26 06:01:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: ret_from_fork_asm+0x11/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task ip:28125 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:ip state:D stack:0 pid:28125 tgid:28125 ppid:3604 flags:0x00004002
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_timeout+0x19c/0x1b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? mark_held_locks+0x49/0x70
Feb 26 06:01:45 ct523c-0b0b kernel: __wait_for_common+0xba/0x1d0
Feb 26 06:01:45 ct523c-0b0b kernel: ? usleep_range_state+0xb0/0xb0
Feb 26 06:01:45 ct523c-0b0b kernel: remove_one+0x6b/0x100
Feb 26 06:01:45 ct523c-0b0b kernel: simple_recursive_removal+0x20c/0x2b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? start_creating.part.0+0x170/0x170
Feb 26 06:01:45 ct523c-0b0b kernel: debugfs_remove+0x3b/0x60
Feb 26 06:01:45 ct523c-0b0b kernel: ieee80211_debugfs_recreate_netdev+0x30/0xac0 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_is_held_type+0xa6/0x110
Feb 26 06:01:45 ct523c-0b0b kernel: drv_remove_interface+0x96/0x210 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ieee80211_do_stop+0x5e7/0x820 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? mark_held_locks+0x49/0x70
Feb 26 06:01:45 ct523c-0b0b kernel: ieee80211_stop+0x51/0x180 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: __dev_close_many+0xa7/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: __dev_change_flags+0x198/0x240
Feb 26 06:01:45 ct523c-0b0b kernel: dev_change_flags+0x1d/0x60
Feb 26 06:01:45 ct523c-0b0b kernel: do_setlink+0x333/0x1160
Feb 26 06:01:45 ct523c-0b0b kernel: ? __nla_validate_parse+0x5f/0xd10
Feb 26 06:01:45 ct523c-0b0b kernel: ? __lock_acquire+0x405/0x2380
Feb 26 06:01:45 ct523c-0b0b kernel: __rtnl_newlink+0x5a2/0x940
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_is_held_type+0xa6/0x110
Feb 26 06:01:45 ct523c-0b0b kernel: ? __kmem_cache_alloc_node+0x10/0x1e0
Feb 26 06:01:45 ct523c-0b0b kernel: ? rtnetlink_rcv_msg+0x93/0x620
Feb 26 06:01:45 ct523c-0b0b kernel: ? rtnl_newlink+0x25/0x60
Feb 26 06:01:45 ct523c-0b0b kernel: rtnl_newlink+0x3e/0x60
Feb 26 06:01:45 ct523c-0b0b kernel: rtnetlink_rcv_msg+0x161/0x620
Feb 26 06:01:45 ct523c-0b0b kernel: ? rtnl_getlink+0x3e0/0x3e0
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_rcv_skb+0x4f/0x100
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_unicast+0x18e/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: netlink_sendmsg+0x257/0x4d0
Feb 26 06:01:45 ct523c-0b0b kernel: __sock_sendmsg+0x33/0x60
Feb 26 06:01:45 ct523c-0b0b kernel: ____sys_sendmsg+0x22c/0x2a0
Feb 26 06:01:45 ct523c-0b0b kernel: ? copy_msghdr_from_user+0x68/0xa0
Feb 26 06:01:45 ct523c-0b0b kernel: ___sys_sendmsg+0x81/0xc0
Feb 26 06:01:45 ct523c-0b0b kernel: ? __lock_acquire+0x405/0x2380
Feb 26 06:01:45 ct523c-0b0b kernel: ? fsnotify_grab_connector+0x41/0x160
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_acquire+0xc6/0x2b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? mntput_no_expire+0x3f/0x410
Feb 26 06:01:45 ct523c-0b0b kernel: ? find_held_lock+0x2b/0x80
Feb 26 06:01:45 ct523c-0b0b kernel: ? mntput_no_expire+0x8d/0x410
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: __sys_sendmsg+0x52/0xa0
Feb 26 06:01:45 ct523c-0b0b kernel: do_syscall_64+0x3b/0x110
Feb 26 06:01:45 ct523c-0b0b kernel: entry_SYSCALL_64_after_hwframe+0x46/0x4e
Feb 26 06:01:45 ct523c-0b0b kernel: RIP: 0033:0x7f4c73f13737
Feb 26 06:01:45 ct523c-0b0b kernel: RSP: 002b:00007ffda71adb38 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
Feb 26 06:01:45 ct523c-0b0b kernel: RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f4c73f13737
Feb 26 06:01:45 ct523c-0b0b kernel: RDX: 0000000000000000 RSI: 00007ffda71adba0 RDI: 0000000000000004
Feb 26 06:01:45 ct523c-0b0b kernel: RBP: 0000000065dc9874 R08: 0000000000000010 R09: 0000000000000060
Feb 26 06:01:45 ct523c-0b0b kernel: R10: 00007f4c73e0df08 R11: 0000000000000246 R12: 00007ffda71adba0
Feb 26 06:01:45 ct523c-0b0b kernel: R13: 0000000000496560 R14: 0000000000000000 R15: 00007f4c741e0000
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task cat:28128 blocked for more than 180 seconds.
Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:01:45 ct523c-0b0b kernel: task:cat state:D stack:0 pid:28128 tgid:28128 ppid:28123 flags:0x00000002
Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:01:45 ct523c-0b0b kernel: schedule_timeout+0x19c/0x1b0
Feb 26 06:01:45 ct523c-0b0b kernel: ? __wait_for_common+0xb1/0x1d0
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: __wait_for_common+0xba/0x1d0
Feb 26 06:01:45 ct523c-0b0b kernel: ? usleep_range_state+0xb0/0xb0
Feb 26 06:01:45 ct523c-0b0b kernel: wiphy_locked_debugfs_read+0x111/0x180 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? wiphy_locked_debugfs_write_work+0x30/0x30 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? rts_threshold_read+0x80/0x80 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ieee80211_if_read_sdata+0x55/0x80 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? ieee80211_link_sta_debugfs_drv_remove+0x40/0x40 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: ? ieee80211_if_fmt_dot11MeshMaxRetries+0x20/0x20 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: full_proxy_read+0x51/0x70
Feb 26 06:01:45 ct523c-0b0b kernel: vfs_read+0xa3/0x2c0
Feb 26 06:01:45 ct523c-0b0b kernel: ? find_held_lock+0x2b/0x80
Feb 26 06:01:45 ct523c-0b0b kernel: ? do_user_addr_fault+0x371/0x850
Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:01:45 ct523c-0b0b kernel: ksys_read+0x64/0xe0
Feb 26 06:01:45 ct523c-0b0b kernel: do_syscall_64+0x3b/0x110
Feb 26 06:01:45 ct523c-0b0b kernel: entry_SYSCALL_64_after_hwframe+0x46/0x4e
Feb 26 06:01:45 ct523c-0b0b kernel: RIP: 0033:0x7f6af1901b92
Feb 26 06:01:45 ct523c-0b0b kernel: RSP: 002b:00007ffd1a1972a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
Feb 26 06:01:45 ct523c-0b0b kernel: RAX: ffffffffffffffda RBX: 00007f6af1a49000 RCX: 00007f6af1901b92
Feb 26 06:01:45 ct523c-0b0b kernel: RDX: 0000000000020000 RSI: 00007f6af1a49000 RDI: 0000000000000003
Feb 26 06:01:45 ct523c-0b0b kernel: RBP: 0000000000020000 R08: 00000000ffffffff R09: 0000000000000000
Feb 26 06:01:45 ct523c-0b0b kernel: R10: 0000000000000022 R11: 0000000000000246 R12: 00007f6af1a49000
Feb 26 06:01:45 ct523c-0b0b kernel: R13: 0000000000000003 R14: 0000000000000000 R15: 0000000000020000
Feb 26 06:01:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:01:45 ct523c-0b0b kernel:
Showing all locks held in the system:
Feb 26 06:01:45 ct523c-0b0b kernel: 1 lock held by khungtaskd/66:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff8296d640 (rcu_read_lock){....}-{1:3}, at: debug_show_all_locks+0x32/0x1c0
Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by kworker/6:3/542:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffff888109b33b38 ((wq_completion)ipv6_addrconf){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffffc90000f77e58 ((work_completion)(&(&net->ipv6.addr_chk_work)->work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: 1 lock held by ntpd/1448:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: __netlink_dump_start+0x7d/0x290
Feb 26 06:01:45 ct523c-0b0b kernel: 1 lock held by fuse mainloop/2633:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffff8881230a6668 (&pipe->mutex/1){+.+.}-{4:4}, at: splice_file_to_pipe+0x21/0xc0
Feb 26 06:01:45 ct523c-0b0b kernel: 1 lock held by fuse mainloop/2634:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffff88812cb63068 (&pipe->mutex/1){+.+.}-{4:4}, at: splice_file_to_pipe+0x21/0xc0
Feb 26 06:01:45 ct523c-0b0b kernel: 1 lock held by gnuserver/3271:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: dev_ethtool+0x9e/0x29b0
Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by kworker/u16:1/8298:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffff888108058d38 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffffc9000abcfe58 ((work_completion)(&rdev->wiphy_work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: 2 locks held by wpa_supplicant/26601:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff82a7a630 (cb_lock){++++}-{4:4}, at: genl_rcv+0x10/0x30
Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: nl80211_pre_doit+0x1f/0x250 [cfg80211]
Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by kworker/3:1/27514:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffff888109b33b38 ((wq_completion)ipv6_addrconf){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffffc900089fbe58 ((work_completion)(&(&net->ipv6.addr_chk_work)->work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: addrconf_verify_work+0x9/0x20
Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by ip/28125:
Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: rtnetlink_rcv_msg+0x13e/0x620
Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: ieee80211_stop+0x2d/0x180 [mac80211]
Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffff88812661d768 (&sb->s_type->i_mutex_key#3){++++}-{4:4}, at: simple_recursive_removal+0x189/0x2b0
Feb 26 06:01:45 ct523c-0b0b kernel:
Feb 26 06:01:45 ct523c-0b0b kernel: =============================================
Feb 26 06:04:01 ct523c-0b0b dhcpd[24940]: DHCPREQUEST for 172.16.222.81 from 94:1c:56:bf:fa:61 (GRBE330C-FA60) via eth2
Feb 26 06:04:01 ct523c-0b0b dhcpd[24940]: DHCPACK on 172.16.222.81 to 94:1c:56:bf:fa:61 (GRBE330C-FA60) via eth2
Feb 26 06:04:45 ct523c-0b0b kernel: INFO: task kworker/6:3:542 blocked for more than 360 seconds.
Feb 26 06:04:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:04:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:04:45 ct523c-0b0b kernel: task:kworker/6:3 state:D stack:0 pid:542 tgid:542 ppid:2 flags:0x00004000
Feb 26 06:04:45 ct523c-0b0b kernel: Workqueue: ipv6_addrconf addrconf_verify_work
Feb 26 06:04:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:04:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:04:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:04:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:04:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:04:45 ct523c-0b0b kernel: ? lock_acquire+0xc6/0x2b0
Feb 26 06:04:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: addrconf_verify_work+0x9/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: process_one_work+0x1f6/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: worker_thread+0x1cc/0x3b0
Feb 26 06:04:45 ct523c-0b0b kernel: ? wq_sysfs_prep_attrs+0x90/0x90
Feb 26 06:04:45 ct523c-0b0b kernel: kthread+0xec/0x120
Feb 26 06:04:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: ret_from_fork+0x28/0x40
Feb 26 06:04:45 ct523c-0b0b kernel: ? kthread_complete_and_exit+0x20/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: ret_from_fork_asm+0x11/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:04:45 ct523c-0b0b kernel: INFO: task ntpd:1448 blocked for more than 360 seconds.
Feb 26 06:04:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
Feb 26 06:04:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 26 06:04:45 ct523c-0b0b kernel: task:ntpd state:D stack:0 pid:1448 tgid:1448 ppid:1 flags:0x00000006
Feb 26 06:04:45 ct523c-0b0b kernel: Call Trace:
Feb 26 06:04:45 ct523c-0b0b kernel: <TASK>
Feb 26 06:04:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
Feb 26 06:04:45 ct523c-0b0b kernel: schedule+0x3c/0x120
Feb 26 06:04:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
Feb 26 06:04:45 ct523c-0b0b kernel: ? netlink_lookup+0x13b/0x2f0
Feb 26 06:04:45 ct523c-0b0b kernel: ? __netlink_dump_start+0x7d/0x290
Feb 26 06:04:45 ct523c-0b0b kernel: ? __netlink_dump_start+0x7d/0x290
Feb 26 06:04:45 ct523c-0b0b kernel: __netlink_dump_start+0x7d/0x290
Feb 26 06:04:45 ct523c-0b0b kernel: ? rtnl_fill_ifinfo+0x1960/0x1960
Feb 26 06:04:45 ct523c-0b0b kernel: rtnetlink_rcv_msg+0x4d1/0x620
Feb 26 06:04:45 ct523c-0b0b kernel: ? rtnl_fill_ifinfo+0x1960/0x1960
Feb 26 06:04:45 ct523c-0b0b kernel: ? rtnl_getlink+0x3e0/0x3e0
Feb 26 06:04:45 ct523c-0b0b kernel: netlink_rcv_skb+0x4f/0x100
Feb 26 06:04:45 ct523c-0b0b kernel: netlink_unicast+0x18e/0x270
Feb 26 06:04:45 ct523c-0b0b kernel: netlink_sendmsg+0x257/0x4d0
Feb 26 06:04:45 ct523c-0b0b kernel: __sock_sendmsg+0x33/0x60
Feb 26 06:04:45 ct523c-0b0b kernel: __sys_sendto+0xef/0x130
Feb 26 06:04:45 ct523c-0b0b kernel: ? lock_release+0xc5/0x270
Feb 26 06:04:45 ct523c-0b0b kernel: ? fd_install+0xb8/0x2e0
Feb 26 06:04:45 ct523c-0b0b kernel: ? __sys_socket+0xc1/0xf0
Feb 26 06:04:45 ct523c-0b0b kernel: __x64_sys_sendto+0x1b/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: do_syscall_64+0x3b/0x110
Feb 26 06:04:45 ct523c-0b0b kernel: entry_SYSCALL_64_after_hwframe+0x46/0x4e
Feb 26 06:04:45 ct523c-0b0b kernel: RIP: 0033:0x7f14ccd13834
Feb 26 06:04:45 ct523c-0b0b kernel: RSP: 002b:00007ffdaa403950 EFLAGS: 00000293 ORIG_RAX: 000000000000002c
Feb 26 06:04:45 ct523c-0b0b kernel: RAX: ffffffffffffffda RBX: 00007ffdaa4049e0 RCX: 00007f14ccd13834
Feb 26 06:04:45 ct523c-0b0b kernel: RDX: 0000000000000014 RSI: 00007ffdaa404a20 RDI: 0000000000000004
Feb 26 06:04:45 ct523c-0b0b kernel: RBP: 0000000000000000 R08: 00007ffdaa4049e0 R09: 000000000000000c
Feb 26 06:04:45 ct523c-0b0b kernel: R10: 0000000000000000 R11: 0000000000000293 R12: 00007ffdaa404a20
Feb 26 06:04:45 ct523c-0b0b kernel: R13: 000055a0c5771010 R14: 00007ffdaa403990 R15: 00007ffdaa404ae0
Feb 26 06:04:45 ct523c-0b0b kernel: </TASK>
Feb 26 06:04:45 ct523c-0b0b kernel: Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings
Feb 26 06:04:45 ct523c-0b0b kernel:
Showing all locks held in the system:
Feb 26 06:04:45 ct523c-0b0b kernel: 1 lock held by khungtaskd/66:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffffffff8296d640 (rcu_read_lock){....}-{1:3}, at: debug_show_all_locks+0x32/0x1c0
Feb 26 06:04:45 ct523c-0b0b kernel: 3 locks held by kworker/6:3/542:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffff888109b33b38 ((wq_completion)ipv6_addrconf){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: #1: ffffc90000f77e58 ((work_completion)(&(&net->ipv6.addr_chk_work)->work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: #2: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: addrconf_verify_work+0x9/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: 1 lock held by ntpd/1448:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: __netlink_dump_start+0x7d/0x290
Feb 26 06:04:45 ct523c-0b0b kernel: 1 lock held by fuse mainloop/2633:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffff8881230a6668 (&pipe->mutex/1){+.+.}-{4:4}, at: splice_file_to_pipe+0x21/0xc0
Feb 26 06:04:45 ct523c-0b0b kernel: 1 lock held by fuse mainloop/2634:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffff88812cb63068 (&pipe->mutex/1){+.+.}-{4:4}, at: splice_file_to_pipe+0x21/0xc0
Feb 26 06:04:45 ct523c-0b0b kernel: 1 lock held by gnuserver/3271:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: dev_ethtool+0x9e/0x29b0
Feb 26 06:04:45 ct523c-0b0b kernel: 3 locks held by kworker/u16:1/8298:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffff888108058d38 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: #1: ffffc9000abcfe58 ((work_completion)(&rdev->wiphy_work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: #2: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
Feb 26 06:04:45 ct523c-0b0b kernel: 2 locks held by wpa_supplicant/26601:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffffffff82a7a630 (cb_lock){++++}-{4:4}, at: genl_rcv+0x10/0x30
Feb 26 06:04:45 ct523c-0b0b kernel: #1: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: nl80211_pre_doit+0x1f/0x250 [cfg80211]
Feb 26 06:04:45 ct523c-0b0b kernel: 3 locks held by kworker/3:1/27514:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffff888109b33b38 ((wq_completion)ipv6_addrconf){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: #1: ffffc900089fbe58 ((work_completion)(&(&net->ipv6.addr_chk_work)->work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
Feb 26 06:04:45 ct523c-0b0b kernel: #2: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: addrconf_verify_work+0x9/0x20
Feb 26 06:04:45 ct523c-0b0b kernel: 3 locks held by ip/28125:
Feb 26 06:04:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: rtnetlink_rcv_msg+0x13e/0x620
Feb 26 06:04:45 ct523c-0b0b kernel: #1: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: ieee80211_stop+0x2d/0x180 [mac80211]
Feb 26 06:04:45 ct523c-0b0b kernel: #2: ffff88812661d768 (&sb->s_type->i_mutex_key#3){++++}-{4:4}, at: simple_recursive_removal+0x189/0x2b0
Feb 26 06:04:45 ct523c-0b0b kernel: 3 locks held by sadc/28824:
Feb 26 06:04:45 ct523c-0b0b kernel:
Feb 26 06:04:45 ct523c-0b0b kernel: =============================================
Thanks,
Ben
>
> johannes
>
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
On Mon, 2024-02-26 at 06:58 -0800, Ben Greear wrote:
> I managed to catch it in a lockdep enabled kernel. There were no lockdep
> warnings, but more lock info was printed at least:
>
> Maybe ordering of this one's lock printout means it is 'ip' that is actually holding the rtnl?
>
> [Seen in context further below]
> Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by ip/28125:
> Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: rtnetlink_rcv_msg+0x13e/0x620
> Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: ieee80211_stop+0x2d/0x180 [mac80211]
> Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffff88812661d768 (&sb->s_type->i_mutex_key#3){++++}-{4:4}, at: simple_recursive_removal+0x189/0x2b0
Yes, probably.
> Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task kworker/6:3:542 blocked for more than 180 seconds.
> Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
> Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Feb 26 06:01:45 ct523c-0b0b kernel: task:kworker/6:3 state:D stack:0 pid:542 tgid:542 ppid:2 flags:0x00004000
> Feb 26 06:01:45 ct523c-0b0b kernel: Workqueue: ipv6_addrconf addrconf_verify_work
> Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
> Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
> Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
> Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
> Feb 26 06:01:45 ct523c-0b0b kernel: ? lock_acquire+0xc6/0x2b0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
> Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? addrconf_verify_work+0x9/0x20
> Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
> Feb 26 06:01:45 ct523c-0b0b kernel: addrconf_verify_work+0x9/0x20
Lots of things like this are just blocked on RTNL.
> Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Feb 26 06:01:45 ct523c-0b0b kernel: task:kworker/u16:1 state:D stack:0 pid:8298 tgid:8298 ppid:2 flags:0x00004000
> Feb 26 06:01:45 ct523c-0b0b kernel: Workqueue: events_unbound cfg80211_wiphy_work [cfg80211]
> Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
> Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
> Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule_preempt_disabled+0xc/0x20
> Feb 26 06:01:45 ct523c-0b0b kernel: __mutex_lock+0x5c4/0xc00
> Feb 26 06:01:45 ct523c-0b0b kernel: ? cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
> Feb 26 06:01:45 ct523c-0b0b kernel: ? process_one_work+0x18f/0x4e0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
> Feb 26 06:01:45 ct523c-0b0b kernel: cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
this is blocked on wiphy mutex.
> Feb 26 06:01:45 ct523c-0b0b kernel: INFO: task ip:28125 blocked for more than 180 seconds.
> Feb 26 06:01:45 ct523c-0b0b kernel: Not tainted 6.7.5+ #1
> Feb 26 06:01:45 ct523c-0b0b kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Feb 26 06:01:45 ct523c-0b0b kernel: task:ip state:D stack:0 pid:28125 tgid:28125 ppid:3604 flags:0x00004002
> Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
> Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
> Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule_timeout+0x19c/0x1b0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? mark_held_locks+0x49/0x70
> Feb 26 06:01:45 ct523c-0b0b kernel: __wait_for_common+0xba/0x1d0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? usleep_range_state+0xb0/0xb0
> Feb 26 06:01:45 ct523c-0b0b kernel: remove_one+0x6b/0x100
> Feb 26 06:01:45 ct523c-0b0b kernel: simple_recursive_removal+0x20c/0x2b0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? start_creating.part.0+0x170/0x170
> Feb 26 06:01:45 ct523c-0b0b kernel: debugfs_remove+0x3b/0x60
> Feb 26 06:01:45 ct523c-0b0b kernel: ieee80211_debugfs_recreate_netdev+0x30/0xac0 [mac80211]
This seems to be blocked on the wait_for_completion()?! Which means it
should have actually triggered the c->cancel() first, but ... if
wiphy_locked_debugfs_read_cancel() had actually been called, I'm not
sure why we'd be stuck here?
Then again, I'm looking at the code now and not sure why I put this
+ /* if we're already removing wake it up to cancel */
+ if (d_unlinked(dentry))
+ complete(&fsd->active_users_drained);
into debugfs_enter_cancellation()...
> Feb 26 06:01:45 ct523c-0b0b kernel:
> Showing all locks held in the system:
This isn't always clear on holding vs. acquiring, FWIW.
> Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by kworker/6:3/542:
> Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffff888109b33b38 ((wq_completion)ipv6_addrconf){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
> Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffffc90000f77e58 ((work_completion)(&(&net->ipv6.addr_chk_work)->work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
> Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: addrconf_verify_work+0x9/0x20
See this, it's actually stuck on acquiring the RTNL.
> Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by kworker/u16:1/8298:
> Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffff888108058d38 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
> Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffffc9000abcfe58 ((work_completion)(&rdev->wiphy_work)){+.+.}-{0:0}, at: process_one_work+0x18f/0x4e0
> Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: cfg80211_wiphy_work+0x1a/0xc0 [cfg80211]
And this is stuck trying to acquire the wiphy mutex.
> Feb 26 06:01:45 ct523c-0b0b kernel: 3 locks held by ip/28125:
> Feb 26 06:01:45 ct523c-0b0b kernel: #0: ffffffff82a6d588 (rtnl_mutex){+.+.}-{4:4}, at: rtnetlink_rcv_msg+0x13e/0x620
> Feb 26 06:01:45 ct523c-0b0b kernel: #1: ffff888122e60768 (&rdev->wiphy.mtx){+.+.}-{4:4}, at: ieee80211_stop+0x2d/0x180 [mac80211]
> Feb 26 06:01:45 ct523c-0b0b kernel: #2: ffff88812661d768 (&sb->s_type->i_mutex_key#3){++++}-{4:4}, at: simple_recursive_removal+0x189/0x2b0
This has them all.
johannes
> Feb 26 06:01:45 ct523c-0b0b kernel: task:ip state:D stack:0 pid:28125 tgid:28125 ppid:3604 flags:0x00004002
> Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
> Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
> Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
> Feb 26 06:01:45 ct523c-0b0b kernel: schedule_timeout+0x19c/0x1b0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? mark_held_locks+0x49/0x70
> Feb 26 06:01:45 ct523c-0b0b kernel: __wait_for_common+0xba/0x1d0
> Feb 26 06:01:45 ct523c-0b0b kernel: ? usleep_range_state+0xb0/0xb0
> Feb 26 06:01:45 ct523c-0b0b kernel: remove_one+0x6b/0x100
Can you say where this remove_one+0x6b is?
I feel it's probably this:
if (!refcount_dec_and_test(&fsd->active_users)) {
wait_for_completion(&fsd->active_users_drained);
which ... looking at it, seems wrong?
_Completely_ untested:
diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
index 034a617cb1a5..fb636478c54d 100644
--- a/fs/debugfs/inode.c
+++ b/fs/debugfs/inode.c
@@ -751,13 +751,19 @@ static void __debugfs_file_removed(struct dentry *dentry)
if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
return;
- /* if we hit zero, just wait for all to finish */
- if (!refcount_dec_and_test(&fsd->active_users)) {
- wait_for_completion(&fsd->active_users_drained);
- return;
- }
+ /*
+ * Now that debugfs_file_get() no longer sees a valid entry,
+ * decrement the refcount to remove the initial reference.
+ */
+ refcount_dec(&fsd->active_users);
- /* if we didn't hit zero, try to cancel any we can */
+ /*
+ * As long as it's not zero, try to cancel any cancellations,
+ * new incoming ones will wake up the completion as we might
+ * have raced: debugfs_file_get() had already been done, but
+ * debugfs_enter_cancellation() hadn't, by the time we got
+ * to this point here.
+ */
while (refcount_read(&fsd->active_users)) {
struct debugfs_cancellation *c;
johannes
On 2/27/24 05:47, Johannes Berg wrote:
>
>> Feb 26 06:01:45 ct523c-0b0b kernel: task:ip state:D stack:0 pid:28125 tgid:28125 ppid:3604 flags:0x00004002
>> Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
>> Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
>> Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
>> Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
>> Feb 26 06:01:45 ct523c-0b0b kernel: schedule_timeout+0x19c/0x1b0
>> Feb 26 06:01:45 ct523c-0b0b kernel: ? mark_held_locks+0x49/0x70
>> Feb 26 06:01:45 ct523c-0b0b kernel: __wait_for_common+0xba/0x1d0
>> Feb 26 06:01:45 ct523c-0b0b kernel: ? usleep_range_state+0xb0/0xb0
>> Feb 26 06:01:45 ct523c-0b0b kernel: remove_one+0x6b/0x100
>
> Can you say where this remove_one+0x6b is?
>
> I feel it's probably this:
>
> if (!refcount_dec_and_test(&fsd->active_users)) {
> wait_for_completion(&fsd->active_users_drained);
>
> which ... looking at it, seems wrong?
(gdb) l *(remove_one+0x6b)
0xffffffff815c257b is in remove_one (/home/greearb/git/linux-6.7.dev.y/fs/debugfs/inode.c:757).
752 return;
753
754 /* if we hit zero, just wait for all to finish */
755 if (!refcount_dec_and_test(&fsd->active_users)) {
756 wait_for_completion(&fsd->active_users_drained);
757 return;
758 }
759
760 /* if we didn't hit zero, try to cancel any we can */
761 while (refcount_read(&fsd->active_users)) {
(gdb)
>
> _Completely_ untested:
We can test it.
Thanks,
Ben
>
> diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
> index 034a617cb1a5..fb636478c54d 100644
> --- a/fs/debugfs/inode.c
> +++ b/fs/debugfs/inode.c
> @@ -751,13 +751,19 @@ static void __debugfs_file_removed(struct dentry *dentry)
> if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> return;
>
> - /* if we hit zero, just wait for all to finish */
> - if (!refcount_dec_and_test(&fsd->active_users)) {
> - wait_for_completion(&fsd->active_users_drained);
> - return;
> - }
> + /*
> + * Now that debugfs_file_get() no longer sees a valid entry,
> + * decrement the refcount to remove the initial reference.
> + */
> + refcount_dec(&fsd->active_users);
>
> - /* if we didn't hit zero, try to cancel any we can */
> + /*
> + * As long as it's not zero, try to cancel any cancellations,
> + * new incoming ones will wake up the completion as we might
> + * have raced: debugfs_file_get() had already been done, but
> + * debugfs_enter_cancellation() hadn't, by the time we got
> + * to this point here.
> + */
> while (refcount_read(&fsd->active_users)) {
> struct debugfs_cancellation *c;
>
>
>
>
> johannes
>
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
On 2/27/24 06:32, Johannes Berg wrote:
> On Tue, 2024-02-27 at 06:29 -0800, Ben Greear wrote:
>>> --- a/fs/debugfs/inode.c
>>> +++ b/fs/debugfs/inode.c
>>> @@ -751,13 +751,19 @@ static void __debugfs_file_removed(struct dentry *dentry)
>>> if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
>>> return;
>>>
>>> - /* if we hit zero, just wait for all to finish */
>>> - if (!refcount_dec_and_test(&fsd->active_users)) {
>>> - wait_for_completion(&fsd->active_users_drained);
>>> - return;
>>> - }
>>> + /*
>>> + * Now that debugfs_file_get() no longer sees a valid entry,
>>> + * decrement the refcount to remove the initial reference.
>>> + */
>>> + refcount_dec(&fsd->active_users);
>
>>
>> [ 94.576688] ------------[ cut here ]------------
>> [ 94.576699] refcount_t: decrement hit 0; leaking memory.
>>
>
> Ah ... right, refcount_dec() doesn't like to hit 0, it's not meant for
> this path.
>
> I guess we can
>
> if (refcount_dec_and_test(...))
> return;
>
> while (refcount_read(...)) { ... }
>
> johannes
>
Like this?
diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
index 034a617cb1a5..166053095610 100644
--- a/fs/debugfs/inode.c
+++ b/fs/debugfs/inode.c
@@ -751,13 +751,20 @@ static void __debugfs_file_removed(struct dentry *dentry)
if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
return;
- /* if we hit zero, just wait for all to finish */
- if (!refcount_dec_and_test(&fsd->active_users)) {
- wait_for_completion(&fsd->active_users_drained);
+ /*
+ * Now that debugfs_file_get() no longer sees a valid entry,
+ * decrement the refcount to remove the initial reference.
+ */
+ if (!refcount_dec_and_test(&fsd->active_users))
return;
- }
- /* if we didn't hit zero, try to cancel any we can */
+ /*
+ * As long as it's not zero, try to cancel any cancellations,
+ * new incoming ones will wake up the completion as we might
+ * have raced: debugfs_file_get() had already been done, but
+ * debugfs_enter_cancellation() hadn't, by the time we got
+ * to this point here.
+ */
while (refcount_read(&fsd->active_users)) {
struct debugfs_cancellation *c;
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
On Tue, 2024-02-27 at 06:29 -0800, Ben Greear wrote:
> > --- a/fs/debugfs/inode.c
> > +++ b/fs/debugfs/inode.c
> > @@ -751,13 +751,19 @@ static void __debugfs_file_removed(struct dentry *dentry)
> > if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> > return;
> >
> > - /* if we hit zero, just wait for all to finish */
> > - if (!refcount_dec_and_test(&fsd->active_users)) {
> > - wait_for_completion(&fsd->active_users_drained);
> > - return;
> > - }
> > + /*
> > + * Now that debugfs_file_get() no longer sees a valid entry,
> > + * decrement the refcount to remove the initial reference.
> > + */
> > + refcount_dec(&fsd->active_users);
>
> [ 94.576688] ------------[ cut here ]------------
> [ 94.576699] refcount_t: decrement hit 0; leaking memory.
>
Ah ... right, refcount_dec() doesn't like to hit 0, it's not meant for
this path.
I guess we can
if (refcount_dec_and_test(...))
return;
while (refcount_read(...)) { ... }
johannes
On 2/27/24 05:47, Johannes Berg wrote:
>
>> Feb 26 06:01:45 ct523c-0b0b kernel: task:ip state:D stack:0 pid:28125 tgid:28125 ppid:3604 flags:0x00004002
>> Feb 26 06:01:45 ct523c-0b0b kernel: Call Trace:
>> Feb 26 06:01:45 ct523c-0b0b kernel: <TASK>
>> Feb 26 06:01:45 ct523c-0b0b kernel: __schedule+0x42c/0xde0
>> Feb 26 06:01:45 ct523c-0b0b kernel: schedule+0x3c/0x120
>> Feb 26 06:01:45 ct523c-0b0b kernel: schedule_timeout+0x19c/0x1b0
>> Feb 26 06:01:45 ct523c-0b0b kernel: ? mark_held_locks+0x49/0x70
>> Feb 26 06:01:45 ct523c-0b0b kernel: __wait_for_common+0xba/0x1d0
>> Feb 26 06:01:45 ct523c-0b0b kernel: ? usleep_range_state+0xb0/0xb0
>> Feb 26 06:01:45 ct523c-0b0b kernel: remove_one+0x6b/0x100
>
> Can you say where this remove_one+0x6b is?
>
> I feel it's probably this:
>
> if (!refcount_dec_and_test(&fsd->active_users)) {
> wait_for_completion(&fsd->active_users_drained);
>
> which ... looking at it, seems wrong?
>
> _Completely_ untested:
>
> diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
> index 034a617cb1a5..fb636478c54d 100644
> --- a/fs/debugfs/inode.c
> +++ b/fs/debugfs/inode.c
> @@ -751,13 +751,19 @@ static void __debugfs_file_removed(struct dentry *dentry)
> if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> return;
>
> - /* if we hit zero, just wait for all to finish */
> - if (!refcount_dec_and_test(&fsd->active_users)) {
> - wait_for_completion(&fsd->active_users_drained);
> - return;
> - }
> + /*
> + * Now that debugfs_file_get() no longer sees a valid entry,
> + * decrement the refcount to remove the initial reference.
> + */
> + refcount_dec(&fsd->active_users);
>
> - /* if we didn't hit zero, try to cancel any we can */
> + /*
> + * As long as it's not zero, try to cancel any cancellations,
> + * new incoming ones will wake up the completion as we might
> + * have raced: debugfs_file_get() had already been done, but
> + * debugfs_enter_cancellation() hadn't, by the time we got
> + * to this point here.
> + */
> while (refcount_read(&fsd->active_users)) {
> struct debugfs_cancellation *c;
I see this splat with the patch applied:
[ 94.576688] ------------[ cut here ]------------
[ 94.576699] refcount_t: decrement hit 0; leaking memory.
[ 94.576717] WARNING: CPU: 1 PID: 5686 at lib/refcount.c:31 refcount_warn_saturate+0x42/0xe0
[ 94.576724] Modules linked in: nf_conntrack_netlink nfnetlink xt_MASQUERADE iptable_nat nf_nat iptable_raw xt_CT nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4
bpfilter vrf 8021q garp mrp stp llc macvlan pktgen rpcrdma rdma_cm iw_cm ib_cm ib_core qrtr iTCO_wdt intel_pmc_bxt ee1004 intel_rapl_msr iTCO_vendor_support
snd_hda_codec_hdmi mt7915e mt76_connac_lib snd_hda_codec_realtek snd_hda_codec_generic ledtrig_audio mt76 coretemp intel_rapl_common mac80211 intel_tcc_cooling
snd_hda_intel x86_pkg_temp_thermal intel_powerclamp snd_intel_dspcfg snd_hda_codec intel_wmi_thunderbolt cfg80211 snd_hda_core snd_hwdep pl2303 bfq snd_seq
mei_hdcp mei_pxp snd_seq_device snd_pcm snd_timer i2c_i801 snd intel_pch_thermal soundcore i2c_smbus pcspkr acpi_pad nfsd auth_rpcgss nfs_acl sch_fq_codel lockd
grace sunrpc fuse zram raid1 dm_raid raid456 libcrc32c async_raid6_recov async_memcpy async_pq async_xor xor async_tx raid6_pq i915 drm_buddy intel_gtt
drm_display_helper drm_kms_helper cec igb rc_core i2c_algo_bit ttm drm ixgbe agpgart mdio
[ 94.576822] dca xhci_pci mei_wdt i2c_core xhci_pci_renesas hwmon video wmi [last unloaded: nfnetlink]
[ 94.576833] CPU: 1 PID: 5686 Comm: iw Not tainted 6.7.5+ #2
[ 94.576836] Hardware name: Default string Default string/SKYBAY, BIOS 5.12 08/04/2020
[ 94.576838] RIP: 0010:refcount_warn_saturate+0x42/0xe0
[ 94.576841] Code: 80 3d 24 70 3b 01 00 0f 84 a0 00 00 00 c3 80 3d 15 70 3b 01 00 75 f6 48 c7 c7 10 a5 66 82 c6 05 05 70 3b 01 01 e8 9e a9 a9 ff <0f> 0b c3 80
3d f9 6f 3b 01 00 75 d7 48 c7 c7 90 a4 66 82 c6 05 e9
[ 94.576843] RSP: 0018:ffffc900063df848 EFLAGS: 00010282
[ 94.576846] RAX: 0000000000000000 RBX: ffff88810e752750 RCX: 0000000000000027
[ 94.576848] RDX: ffff88845dc5c708 RSI: 0000000000000001 RDI: ffff88845dc5c700
[ 94.576850] RBP: ffff88811b8af400 R08: 0000000000000000 R09: ffffc900063df6f0
[ 94.576851] R10: 0000000000000003 R11: ffffffff8296a2e8 R12: ffff88811000b1d8
[ 94.576853] R13: ffff88810e7dcea0 R14: 0000000000000000 R15: ffff88810e752868
[ 94.576855] FS: 00007f31ae1f3b80(0000) GS:ffff88845dc40000(0000) knlGS:0000000000000000
[ 94.576857] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 94.576859] CR2: 00007f0533889a90 CR3: 0000000129c8f003 CR4: 00000000003706f0
[ 94.576861] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 94.576862] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 94.576864] Call Trace:
[ 94.576865] <TASK>
[ 94.576867] ? refcount_warn_saturate+0x42/0xe0
[ 94.576869] ? __warn+0x7c/0x170
[ 94.576873] ? refcount_warn_saturate+0x42/0xe0
[ 94.576877] ? report_bug+0x169/0x1a0
[ 94.576883] ? handle_bug+0x41/0x70
[ 94.576887] ? exc_invalid_op+0x13/0x60
[ 94.576890] ? asm_exc_invalid_op+0x16/0x20
[ 94.576900] ? refcount_warn_saturate+0x42/0xe0
[ 94.576903] ? refcount_warn_saturate+0x42/0xe0
[ 94.576905] remove_one+0xde/0xf0
[ 94.576910] simple_recursive_removal+0x20c/0x2b0
[ 94.576914] ? start_creating.part.0+0x170/0x170
[ 94.576919] debugfs_remove+0x3b/0x60
[ 94.576922] ieee80211_debugfs_remove_netdev+0x15/0x30 [mac80211]
[ 94.576998] ieee80211_teardown_sdata+0x13/0x50 [mac80211]
[ 94.577036] unregister_netdevice_many_notify+0x3b9/0x7e0
[ 94.577045] unregister_netdevice_queue+0x84/0xc0
[ 94.577049] _cfg80211_unregister_wdev+0x1c5/0x210 [cfg80211]
[ 94.577117] ieee80211_if_remove+0x9b/0x110 [mac80211]
[ 94.577166] ieee80211_del_iface+0xc/0x10 [mac80211]
[ 94.577220] cfg80211_remove_virtual_intf+0x42/0x120 [cfg80211]
[ 94.577257] genl_family_rcv_msg_doit+0xd1/0x120
[ 94.577267] genl_rcv_msg+0x182/0x290
[ 94.577270] ? __cfg80211_wdev_from_attrs+0x2b0/0x2b0 [cfg80211]
[ 94.577306] ? nl80211_stop_ap+0x30/0x30 [cfg80211]
[ 94.577341] ? nlmsg_trim+0x20/0x20 [cfg80211]
[ 94.577378] ? genl_family_rcv_msg_dumpit+0xf0/0xf0
[ 94.577383] netlink_rcv_skb+0x4f/0x100
[ 94.577392] genl_rcv+0x1f/0x30
[ 94.577395] netlink_unicast+0x18e/0x270
[ 94.577400] netlink_sendmsg+0x257/0x4d0
[ 94.577406] __sock_sendmsg+0x33/0x60
[ 94.577411] ____sys_sendmsg+0x22c/0x2a0
[ 94.577414] ? copy_msghdr_from_user+0x68/0xa0
[ 94.577420] ___sys_sendmsg+0x81/0xc0
[ 94.577424] ? __lock_acquire+0x405/0x2380
[ 94.577430] ? __lock_acquire+0x405/0x2380
[ 94.577435] ? reacquire_held_locks+0xd3/0x1f0
[ 94.577438] ? do_user_addr_fault+0x322/0x850
[ 94.577443] ? lock_acquire+0xc6/0x2b0
[ 94.577448] __sys_sendmsg+0x52/0xa0
[ 94.577456] do_syscall_64+0x3b/0x110
[ 94.577460] entry_SYSCALL_64_after_hwframe+0x46/0x4e
[ 94.577464] RIP: 0033:0x7f31adf13737
[ 94.577467] Code: 0e 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 2e 00 00 00 0f 05 <48> 3d 00 f0
ff ff 77 51 c3 48 83 ec 28 89 54 24 1c 48 89 74 24 10
[ 94.577469] RSP: 002b:00007ffd1e029ae8 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
[ 94.577472] RAX: ffffffffffffffda RBX: 0000000000924390 RCX: 00007f31adf13737
[ 94.577474] RDX: 0000000000000000 RSI: 00007ffd1e029b40 RDI: 0000000000000004
[ 94.577476] RBP: 0000000000929780 R08: 00000000009242a0 R09: 0000000000000000
[ 94.577478] R10: 00007f31ae20a3e0 R11: 0000000000000246 R12: 00000000009298c0
[ 94.577479] R13: 00007ffd1e029b40 R14: 00007ffd1e029c70 R15: 000000000043d280
[ 94.577487] </TASK>
[ 94.577488] irq event stamp: 12053
[ 94.577490] hardirqs last enabled at (12059): [<ffffffff8121af54>] console_unlock+0x114/0x140
[ 94.577495] hardirqs last disabled at (12064): [<ffffffff8121af39>] console_unlock+0xf9/0x140
[ 94.577497] softirqs last enabled at (11844): [<ffffffff81188b97>] __irq_exit_rcu+0x77/0xa0
[ 94.577500] softirqs last disabled at (11839): [<ffffffff81188b97>] __irq_exit_rcu+0x77/0xa0
[ 94.577502] ---[ end trace 0000000000000000 ]---
[ 103.657993] workqueue: gc_worker [nf_conntrack] hogged CPU for >10000us 8 times, consider switching to WQ_UNBOUND
[ 148.747435] workqueue: gc_worker [nf_conntrack] hogged CPU for >10000us 16 times, consider switching to WQ_UNBOUND
Thanks,
Ben
>
>
>
>
> johannes
>
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
On Tue, 2024-02-27 at 06:51 -0800, Ben Greear wrote:
> On 2/27/24 06:32, Johannes Berg wrote:
> > On Tue, 2024-02-27 at 06:29 -0800, Ben Greear wrote:
> > > > --- a/fs/debugfs/inode.c
> > > > +++ b/fs/debugfs/inode.c
> > > > @@ -751,13 +751,19 @@ static void __debugfs_file_removed(struct dentry *dentry)
> > > > if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> > > > return;
> > > >
> > > > - /* if we hit zero, just wait for all to finish */
> > > > - if (!refcount_dec_and_test(&fsd->active_users)) {
> > > > - wait_for_completion(&fsd->active_users_drained);
> > > > - return;
> > > > - }
> > > > + /*
> > > > + * Now that debugfs_file_get() no longer sees a valid entry,
> > > > + * decrement the refcount to remove the initial reference.
> > > > + */
> > > > + refcount_dec(&fsd->active_users);
> >
> > >
> > > [ 94.576688] ------------[ cut here ]------------
> > > [ 94.576699] refcount_t: decrement hit 0; leaking memory.
> > >
> >
> > Ah ... right, refcount_dec() doesn't like to hit 0, it's not meant for
> > this path.
> >
> > I guess we can
> >
> > if (refcount_dec_and_test(...))
> > return;
> >
> > while (refcount_read(...)) { ... }
> >
> > johannes
> >
>
> Like this?
>
> diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
> index 034a617cb1a5..166053095610 100644
> --- a/fs/debugfs/inode.c
> +++ b/fs/debugfs/inode.c
> @@ -751,13 +751,20 @@ static void __debugfs_file_removed(struct dentry *dentry)
> if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> return;
>
> - /* if we hit zero, just wait for all to finish */
> - if (!refcount_dec_and_test(&fsd->active_users)) {
> - wait_for_completion(&fsd->active_users_drained);
> + /*
> + * Now that debugfs_file_get() no longer sees a valid entry,
> + * decrement the refcount to remove the initial reference.
> + */
> + if (!refcount_dec_and_test(&fsd->active_users))
> return;
> - }
>
Which, btw, ignoring comments, braces, whitespace - then really just
removes the line you're getting stuck on.
So actually no ... invert the test?
if (refcount_dec_and_test(...))
return;
If it hit zero here, there's guaranteed to be no user, so we can return.
If it's not zero yet, we might yet go into a new cancellation, so we
need the rest of the function.
johannes
On Tue, 2024-02-27 at 06:51 -0800, Ben Greear wrote:
> On 2/27/24 06:32, Johannes Berg wrote:
> > On Tue, 2024-02-27 at 06:29 -0800, Ben Greear wrote:
> > > > --- a/fs/debugfs/inode.c
> > > > +++ b/fs/debugfs/inode.c
> > > > @@ -751,13 +751,19 @@ static void __debugfs_file_removed(struct dentry *dentry)
> > > > if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> > > > return;
> > > >
> > > > - /* if we hit zero, just wait for all to finish */
> > > > - if (!refcount_dec_and_test(&fsd->active_users)) {
> > > > - wait_for_completion(&fsd->active_users_drained);
> > > > - return;
> > > > - }
> > > > + /*
> > > > + * Now that debugfs_file_get() no longer sees a valid entry,
> > > > + * decrement the refcount to remove the initial reference.
> > > > + */
> > > > + refcount_dec(&fsd->active_users);
> >
> > >
> > > [ 94.576688] ------------[ cut here ]------------
> > > [ 94.576699] refcount_t: decrement hit 0; leaking memory.
> > >
> >
> > Ah ... right, refcount_dec() doesn't like to hit 0, it's not meant for
> > this path.
> >
> > I guess we can
> >
> > if (refcount_dec_and_test(...))
> > return;
> >
> > while (refcount_read(...)) { ... }
> >
> > johannes
> >
>
> Like this?
Yeah, looks about right. But not entirely sure I'm thinking this through
correctly right now ...
> diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
> index 034a617cb1a5..166053095610 100644
> --- a/fs/debugfs/inode.c
> +++ b/fs/debugfs/inode.c
> @@ -751,13 +751,20 @@ static void __debugfs_file_removed(struct dentry *dentry)
> if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> return;
>
> - /* if we hit zero, just wait for all to finish */
> - if (!refcount_dec_and_test(&fsd->active_users)) {
> - wait_for_completion(&fsd->active_users_drained);
> + /*
> + * Now that debugfs_file_get() no longer sees a valid entry,
> + * decrement the refcount to remove the initial reference.
> + */
> + if (!refcount_dec_and_test(&fsd->active_users))
> return;
> - }
>
> - /* if we didn't hit zero, try to cancel any we can */
> + /*
> + * As long as it's not zero, try to cancel any cancellations,
> + * new incoming ones will wake up the completion as we might
> + * have raced: debugfs_file_get() had already been done, but
> + * debugfs_enter_cancellation() hadn't, by the time we got
> + * to this point here.
> + */
> while (refcount_read(&fsd->active_users)) {
> struct debugfs_cancellation *c;
>
>
On Tue, 2024-02-27 at 15:58 +0100, Johannes Berg wrote:
>
> Which, btw, ignoring comments, braces, whitespace - then really just
> removes the line you're getting stuck on.
>
> So actually no ... invert the test?
>
> if (refcount_dec_and_test(...))
> return;
>
> If it hit zero here, there's guaranteed to be no user, so we can return.
>
> If it's not zero yet, we might yet go into a new cancellation, so we
> need the rest of the function.
>
This is what I wrote now:
Subject: [PATCH] debugfs: fix wait/cancellation handling during remove
Ben Greear further reports deadlocks during concurrent debugfs
remove while files are being accessed, even though the code in
question now uses debugfs cancellations. Turns out that despite
all the review on the locking, we missed completely that the
logic is wrong: if the refcount hits zero we can finish (and
need not wait for the completion), but if it doesn't we have
to trigger all the cancellations. As written, we can _never_
get into the loop triggering the cancellations. Fix this, and
explain it better while at it.
Cc: [email protected]
Fixes: 8c88a474357e ("debugfs: add API to allow debugfs operations cancellation")
Reported-by: Ben Greear <[email protected]>
Closes: https://lore.kernel.org/r/[email protected]
Change-Id: I6c7aeff8c9d6628a8bc1ddcf332205a49d801f17
Signed-off-by: Johannes Berg <[email protected]>
---
fs/debugfs/inode.c | 25 ++++++++++++++++++++-----
1 file changed, 20 insertions(+), 5 deletions(-)
diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
index 034a617cb1a5..a40da0065433 100644
--- a/fs/debugfs/inode.c
+++ b/fs/debugfs/inode.c
@@ -751,13 +751,28 @@ static void __debugfs_file_removed(struct dentry *dentry)
if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
return;
- /* if we hit zero, just wait for all to finish */
- if (!refcount_dec_and_test(&fsd->active_users)) {
- wait_for_completion(&fsd->active_users_drained);
+ /* if this was the last reference, we're done */
+ if (refcount_dec_and_test(&fsd->active_users))
return;
- }
- /* if we didn't hit zero, try to cancel any we can */
+ /*
+ * If there's still a reference, the code that obtained it can
+ * be in different states:
+ * - The common case of not using cancellations, or already
+ * after debugfs_leave_cancellation(), where we just need
+ * to wait for debugfs_file_put() which signals the completion;
+ * - inside a cancellation section, i.e. between
+ * debugfs_enter_cancellation() and debugfs_leave_cancellation(),
+ * in which case we need to trigger the ->cancel() function,
+ * and then wait for debugfs_file_put() just like in the
+ * previous case;
+ * - before debugfs_enter_cancellation() (but obviously after
+ * debugfs_file_get()), in which case we may not see the
+ * cancellation in the list on the first round of the loop,
+ * but debugfs_enter_cancellation() signals the completion
+ * after adding it, so this code gets woken up to call the
+ * ->cancel() function.
+ */
while (refcount_read(&fsd->active_users)) {
struct debugfs_cancellation *c;
Can you test it and let me know if that works?
Same as what we discussed, FWIW, other than the comments.
johannes
On 2/27/24 08:13, Johannes Berg wrote:
> On Tue, 2024-02-27 at 15:58 +0100, Johannes Berg wrote:
>>
>> Which, btw, ignoring comments, braces, whitespace - then really just
>> removes the line you're getting stuck on.
>>
>> So actually no ... invert the test?
>>
>> if (refcount_dec_and_test(...))
>> return;
>>
>> If it hit zero here, there's guaranteed to be no user, so we can return.
>>
>> If it's not zero yet, we might yet go into a new cancellation, so we
>> need the rest of the function.
>>
>
> This is what I wrote now:
>
>
> Subject: [PATCH] debugfs: fix wait/cancellation handling during remove
>
> Ben Greear further reports deadlocks during concurrent debugfs
> remove while files are being accessed, even though the code in
> question now uses debugfs cancellations. Turns out that despite
> all the review on the locking, we missed completely that the
> logic is wrong: if the refcount hits zero we can finish (and
> need not wait for the completion), but if it doesn't we have
> to trigger all the cancellations. As written, we can _never_
> get into the loop triggering the cancellations. Fix this, and
> explain it better while at it.
>
> Cc: [email protected]
> Fixes: 8c88a474357e ("debugfs: add API to allow debugfs operations cancellation")
> Reported-by: Ben Greear <[email protected]>
> Closes: https://lore.kernel.org/r/[email protected]
> Change-Id: I6c7aeff8c9d6628a8bc1ddcf332205a49d801f17
> Signed-off-by: Johannes Berg <[email protected]>
> ---
> fs/debugfs/inode.c | 25 ++++++++++++++++++++-----
> 1 file changed, 20 insertions(+), 5 deletions(-)
>
> diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
> index 034a617cb1a5..a40da0065433 100644
> --- a/fs/debugfs/inode.c
> +++ b/fs/debugfs/inode.c
> @@ -751,13 +751,28 @@ static void __debugfs_file_removed(struct dentry *dentry)
> if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> return;
>
> - /* if we hit zero, just wait for all to finish */
> - if (!refcount_dec_and_test(&fsd->active_users)) {
> - wait_for_completion(&fsd->active_users_drained);
> + /* if this was the last reference, we're done */
> + if (refcount_dec_and_test(&fsd->active_users))
> return;
> - }
>
> - /* if we didn't hit zero, try to cancel any we can */
> + /*
> + * If there's still a reference, the code that obtained it can
> + * be in different states:
> + * - The common case of not using cancellations, or already
> + * after debugfs_leave_cancellation(), where we just need
> + * to wait for debugfs_file_put() which signals the completion;
> + * - inside a cancellation section, i.e. between
> + * debugfs_enter_cancellation() and debugfs_leave_cancellation(),
> + * in which case we need to trigger the ->cancel() function,
> + * and then wait for debugfs_file_put() just like in the
> + * previous case;
> + * - before debugfs_enter_cancellation() (but obviously after
> + * debugfs_file_get()), in which case we may not see the
> + * cancellation in the list on the first round of the loop,
> + * but debugfs_enter_cancellation() signals the completion
> + * after adding it, so this code gets woken up to call the
> + * ->cancel() function.
> + */
> while (refcount_read(&fsd->active_users)) {
> struct debugfs_cancellation *c;
>
>
>
> Can you test it and let me know if that works?
>
> Same as what we discussed, FWIW, other than the comments.
Thanks for the patch, I'm adding it to our kernel now and we'll start testing it.
Thanks,
Ben
>
> johannes
>
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
On 2/27/24 08:13, Johannes Berg wrote:
> On Tue, 2024-02-27 at 15:58 +0100, Johannes Berg wrote:
>>
>> Which, btw, ignoring comments, braces, whitespace - then really just
>> removes the line you're getting stuck on.
>>
>> So actually no ... invert the test?
>>
>> if (refcount_dec_and_test(...))
>> return;
>>
>> If it hit zero here, there's guaranteed to be no user, so we can return.
>>
>> If it's not zero yet, we might yet go into a new cancellation, so we
>> need the rest of the function.
>>
>
> This is what I wrote now:
>
>
> Subject: [PATCH] debugfs: fix wait/cancellation handling during remove
We are no longer able to reproduce a lockup, so please feel free to add:
Tested-by: Madhan Sai <[email protected]>
Thanks,
Ben
>
> Ben Greear further reports deadlocks during concurrent debugfs
> remove while files are being accessed, even though the code in
> question now uses debugfs cancellations. Turns out that despite
> all the review on the locking, we missed completely that the
> logic is wrong: if the refcount hits zero we can finish (and
> need not wait for the completion), but if it doesn't we have
> to trigger all the cancellations. As written, we can _never_
> get into the loop triggering the cancellations. Fix this, and
> explain it better while at it.
>
> Cc: [email protected]
> Fixes: 8c88a474357e ("debugfs: add API to allow debugfs operations cancellation")
> Reported-by: Ben Greear <[email protected]>
> Closes: https://lore.kernel.org/r/[email protected]
> Change-Id: I6c7aeff8c9d6628a8bc1ddcf332205a49d801f17
> Signed-off-by: Johannes Berg <[email protected]>
> ---
> fs/debugfs/inode.c | 25 ++++++++++++++++++++-----
> 1 file changed, 20 insertions(+), 5 deletions(-)
>
> diff --git a/fs/debugfs/inode.c b/fs/debugfs/inode.c
> index 034a617cb1a5..a40da0065433 100644
> --- a/fs/debugfs/inode.c
> +++ b/fs/debugfs/inode.c
> @@ -751,13 +751,28 @@ static void __debugfs_file_removed(struct dentry *dentry)
> if ((unsigned long)fsd & DEBUGFS_FSDATA_IS_REAL_FOPS_BIT)
> return;
>
> - /* if we hit zero, just wait for all to finish */
> - if (!refcount_dec_and_test(&fsd->active_users)) {
> - wait_for_completion(&fsd->active_users_drained);
> + /* if this was the last reference, we're done */
> + if (refcount_dec_and_test(&fsd->active_users))
> return;
> - }
>
> - /* if we didn't hit zero, try to cancel any we can */
> + /*
> + * If there's still a reference, the code that obtained it can
> + * be in different states:
> + * - The common case of not using cancellations, or already
> + * after debugfs_leave_cancellation(), where we just need
> + * to wait for debugfs_file_put() which signals the completion;
> + * - inside a cancellation section, i.e. between
> + * debugfs_enter_cancellation() and debugfs_leave_cancellation(),
> + * in which case we need to trigger the ->cancel() function,
> + * and then wait for debugfs_file_put() just like in the
> + * previous case;
> + * - before debugfs_enter_cancellation() (but obviously after
> + * debugfs_file_get()), in which case we may not see the
> + * cancellation in the list on the first round of the loop,
> + * but debugfs_enter_cancellation() signals the completion
> + * after adding it, so this code gets woken up to call the
> + * ->cancel() function.
> + */
> while (refcount_read(&fsd->active_users)) {
> struct debugfs_cancellation *c;
>
>
>
> Can you test it and let me know if that works?
>
> Same as what we discussed, FWIW, other than the comments.
>
> johannes
>
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com