* Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. @ 2024-02-23 17:08 Ben Greear 2024-02-26 8:42 ` Johannes Berg 0 siblings, 1 reply; 14+ messages in thread From: Ben Greear @ 2024-02-23 17:08 UTC (permalink / raw) To: linux-wireless; +Cc: Berg, Johannes 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 <greearb@candelatech.com> Candela Technologies Inc http://www.candelatech.com ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-23 17:08 Kernel deadlock in 6.7.5 + hacks, maybe debugfs related Ben Greear @ 2024-02-26 8:42 ` Johannes Berg 2024-02-26 14:58 ` Ben Greear 0 siblings, 1 reply; 14+ messages in thread From: Johannes Berg @ 2024-02-26 8:42 UTC (permalink / raw) To: Ben Greear, linux-wireless 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-26 8:42 ` Johannes Berg @ 2024-02-26 14:58 ` Ben Greear 2024-02-26 15:46 ` Johannes Berg 2024-02-27 13:47 ` Johannes Berg 0 siblings, 2 replies; 14+ messages in thread From: Ben Greear @ 2024-02-26 14:58 UTC (permalink / raw) To: Johannes Berg, linux-wireless 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 <greearb@candelatech.com> Candela Technologies Inc http://www.candelatech.com ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-26 14:58 ` Ben Greear @ 2024-02-26 15:46 ` Johannes Berg 2024-02-27 13:47 ` Johannes Berg 1 sibling, 0 replies; 14+ messages in thread From: Johannes Berg @ 2024-02-26 15:46 UTC (permalink / raw) To: Ben Greear, linux-wireless 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-26 14:58 ` Ben Greear 2024-02-26 15:46 ` Johannes Berg @ 2024-02-27 13:47 ` Johannes Berg 2024-02-27 13:51 ` Ben Greear 2024-02-27 14:29 ` Ben Greear 1 sibling, 2 replies; 14+ messages in thread From: Johannes Berg @ 2024-02-27 13:47 UTC (permalink / raw) To: Ben Greear, linux-wireless > 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 ^ permalink raw reply related [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 13:47 ` Johannes Berg @ 2024-02-27 13:51 ` Ben Greear 2024-02-27 14:29 ` Ben Greear 1 sibling, 0 replies; 14+ messages in thread From: Ben Greear @ 2024-02-27 13:51 UTC (permalink / raw) To: Johannes Berg, linux-wireless 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 <greearb@candelatech.com> Candela Technologies Inc http://www.candelatech.com ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 13:47 ` Johannes Berg 2024-02-27 13:51 ` Ben Greear @ 2024-02-27 14:29 ` Ben Greear 2024-02-27 14:32 ` Johannes Berg 1 sibling, 1 reply; 14+ messages in thread From: Ben Greear @ 2024-02-27 14:29 UTC (permalink / raw) To: Johannes Berg, linux-wireless 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 <greearb@candelatech.com> Candela Technologies Inc http://www.candelatech.com ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 14:29 ` Ben Greear @ 2024-02-27 14:32 ` Johannes Berg 2024-02-27 14:51 ` Ben Greear 0 siblings, 1 reply; 14+ messages in thread From: Johannes Berg @ 2024-02-27 14:32 UTC (permalink / raw) To: Ben Greear, linux-wireless 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 14:32 ` Johannes Berg @ 2024-02-27 14:51 ` Ben Greear 2024-02-27 14:56 ` Johannes Berg 2024-02-27 14:58 ` Johannes Berg 0 siblings, 2 replies; 14+ messages in thread From: Ben Greear @ 2024-02-27 14:51 UTC (permalink / raw) To: Johannes Berg, linux-wireless 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 <greearb@candelatech.com> Candela Technologies Inc http://www.candelatech.com ^ permalink raw reply related [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 14:51 ` Ben Greear @ 2024-02-27 14:56 ` Johannes Berg 2024-02-27 14:58 ` Johannes Berg 1 sibling, 0 replies; 14+ messages in thread From: Johannes Berg @ 2024-02-27 14:56 UTC (permalink / raw) To: Ben Greear, linux-wireless 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; > > ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 14:51 ` Ben Greear 2024-02-27 14:56 ` Johannes Berg @ 2024-02-27 14:58 ` Johannes Berg 2024-02-27 16:13 ` Johannes Berg 1 sibling, 1 reply; 14+ messages in thread From: Johannes Berg @ 2024-02-27 14:58 UTC (permalink / raw) To: Ben Greear, linux-wireless 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 14:58 ` Johannes Berg @ 2024-02-27 16:13 ` Johannes Berg 2024-02-27 17:25 ` Ben Greear 2024-02-29 4:05 ` Ben Greear 0 siblings, 2 replies; 14+ messages in thread From: Johannes Berg @ 2024-02-27 16:13 UTC (permalink / raw) To: Ben Greear, linux-wireless 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: stable@vger.kernel.org Fixes: 8c88a474357e ("debugfs: add API to allow debugfs operations cancellation") Reported-by: Ben Greear <greearb@candelatech.com> Closes: https://lore.kernel.org/r/1c9fa9e5-09f1-0522-fdbc-dbcef4d255ca@candelatech.com Change-Id: I6c7aeff8c9d6628a8bc1ddcf332205a49d801f17 Signed-off-by: Johannes Berg <johannes.berg@intel.com> --- 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 ^ permalink raw reply related [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 16:13 ` Johannes Berg @ 2024-02-27 17:25 ` Ben Greear 2024-02-29 4:05 ` Ben Greear 1 sibling, 0 replies; 14+ messages in thread From: Ben Greear @ 2024-02-27 17:25 UTC (permalink / raw) To: Johannes Berg, linux-wireless 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: stable@vger.kernel.org > Fixes: 8c88a474357e ("debugfs: add API to allow debugfs operations cancellation") > Reported-by: Ben Greear <greearb@candelatech.com> > Closes: https://lore.kernel.org/r/1c9fa9e5-09f1-0522-fdbc-dbcef4d255ca@candelatech.com > Change-Id: I6c7aeff8c9d6628a8bc1ddcf332205a49d801f17 > Signed-off-by: Johannes Berg <johannes.berg@intel.com> > --- > 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 <greearb@candelatech.com> Candela Technologies Inc http://www.candelatech.com ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: Kernel deadlock in 6.7.5 + hacks, maybe debugfs related. 2024-02-27 16:13 ` Johannes Berg 2024-02-27 17:25 ` Ben Greear @ 2024-02-29 4:05 ` Ben Greear 1 sibling, 0 replies; 14+ messages in thread From: Ben Greear @ 2024-02-29 4:05 UTC (permalink / raw) To: Johannes Berg, linux-wireless; +Cc: Madhan Sai 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 <madhan.singaraju@candelatech.com> 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: stable@vger.kernel.org > Fixes: 8c88a474357e ("debugfs: add API to allow debugfs operations cancellation") > Reported-by: Ben Greear <greearb@candelatech.com> > Closes: https://lore.kernel.org/r/1c9fa9e5-09f1-0522-fdbc-dbcef4d255ca@candelatech.com > Change-Id: I6c7aeff8c9d6628a8bc1ddcf332205a49d801f17 > Signed-off-by: Johannes Berg <johannes.berg@intel.com> > --- > 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 <greearb@candelatech.com> Candela Technologies Inc http://www.candelatech.com ^ permalink raw reply [flat|nested] 14+ messages in thread
end of thread, other threads:[~2024-02-29 4:05 UTC | newest] Thread overview: 14+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2024-02-23 17:08 Kernel deadlock in 6.7.5 + hacks, maybe debugfs related Ben Greear 2024-02-26 8:42 ` Johannes Berg 2024-02-26 14:58 ` Ben Greear 2024-02-26 15:46 ` Johannes Berg 2024-02-27 13:47 ` Johannes Berg 2024-02-27 13:51 ` Ben Greear 2024-02-27 14:29 ` Ben Greear 2024-02-27 14:32 ` Johannes Berg 2024-02-27 14:51 ` Ben Greear 2024-02-27 14:56 ` Johannes Berg 2024-02-27 14:58 ` Johannes Berg 2024-02-27 16:13 ` Johannes Berg 2024-02-27 17:25 ` Ben Greear 2024-02-29 4:05 ` Ben Greear
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox