On 13/02/2025 16:46, Sabrina Dubroca wrote:
2025-02-13, 12:46:34 +0100, Antonio Quartulli wrote:
On 13/02/2025 00:34, Sabrina Dubroca wrote:
Hello,
2025-02-11, 01:39:53 +0100, Antonio Quartulli wrote:
All minor and major reported problems have been finally addressed. Big thanks to Sabrina, who took the time to guide me through converting the peer socket to an RCU pointer.
Something is off (not sure if it's new to this version): if I use test-tcp.sh to setup a set of interfaces and peers (I stop the test just after setup to keep the environment alive), then remove all netns with "ip -all netns delete", I expect all devices to go away, but they don't. With debug messages enabled I'm seeing some activity from the module ("tun0: sending keepalive to peer 3" and so on), and ovpn_net_uninit/ovpn_priv_free never got called.
I can reproduce it. If later I rmmod ovpn I then get all the "Deleting peer" messages. So instances are not being purged on netns exit.
Will dive into it.
I think the socket holds a ref on the netns, so it's not getting destroyed, simply "removed" from iproute's point of view. And the socket isn't going away as long as it's used by a peer.
After a deep dive I was getting to the same conclusion: cleanup_net() is never invoked because we lack an invocation of put_net(). sk_alloc() invokes get_net(), so this is the ref that is not being released.
If I delete the peer(s) for the ovpn device and then the netns it was in, the netns is fully removed, and the ovpn device is gone. Also no issue if I delete the ovpn device before its netns, then everything is destroyed as expected.
I'm not sure that can be solved, as least under the current refcount scheme.
I went back to v12 of the patchset (which is pre-refcount-restructuring) and indeed the problem there doesn't exist.
However, it's unclear to me how in v12 the socket release was happening upon netns delete. Who was triggering that? ovpn still needed to call sockfd_put() in order to let it go.
Will investigate some more and think about a solution.
But I don't think there's a way to re-attach to that netns afterwards if we wanted to clean up manually (something similar to "ip netns attach <name> <pid>", but that won't work if whatever created the socket is not running anymore -- as is the case with ovpn-cli).
Yeah, it just hangs in background until reboot.
[...]
So there is NO risk of deadlock (and indeed nothing hangs), but I couldn't find a way to make the warning go away.
I've spotted another splat on strparser cleanup that looked like an actual deadlock, but it's not very reproducible. Still looking into it, but I'm not convinced it's ok to call strp_done (as is done from ovpn_tcp_socket_detach) while under lock_sock, because AFAIU cancel_work_sync(&strp->work) may be waiting for a work that needs to lock the socket (cb.lock in do_strp_work). I guess tcp_tx_work would have the same problem.
Will have a look here too.
Thanks for all the info below. I will have a deeper look at this tomorrow.
Regards,
The only ways I've managed to reproduce it is by using some ugly kernel-side hacks to try to force that path being hit. Either forcing the strp work to be queued just as we detach the socket (in strp_stop), or this:
- hack some code path to do a big sleep() under lock_sock(), to give me the time to do the next steps
- ping over ovpn, or any other way to add packets on the receive socket
- delete the peer for the sleeping socket (while it's still sleeping)
When that big sleep is over, strp_data_ready will kick off and queue its worker (because at this point the socket lock is still owned), then I think del_peer proceeds toward tcp_detach and I got the splat below. So that's maybe a bit hard to trigger in real life (I don't remember what I was doing the first time I got it, I think something messing with the RCU stuff we discussed earlier).
[ 922.681435][ T300] ====================================================== [ 922.686247][ T300] WARNING: possible circular locking dependency detected [ 922.690971][ T300] 6.14.0-rc1-net-00276-g95f1f7ea224e-dirty #279 Tainted: G N [ 922.696584][ T300] ------------------------------------------------------ [ 922.699697][ T300] kworker/1:2/300 is trying to acquire lock: [ 922.702105][ T300] ffff88800a662160 ((work_completion)(&strp->work)){+.+.}-{0:0}, at: start_flush_work+0x407/0xa50 [ 922.705716][ T300] [ 922.705716][ T300] but task is already holding lock: [ 922.707779][ T300] ffff8880113edd98 (sk_lock-AF_INET){+.+.}-{0:0}, at: ovpn_socket_release+0x8a/0x1a0 [ 922.710238][ T300] [ 922.710238][ T300] which lock already depends on the new lock. [ 922.710238][ T300] [ 922.712628][ T300] [ 922.712628][ T300] the existing dependency chain (in reverse order) is: [ 922.714443][ T300] [ 922.714443][ T300] -> #1 (sk_lock-AF_INET){+.+.}-{0:0}: [ 922.716127][ T300] __lock_acquire+0xc4d/0x1ee0 [ 922.717250][ T300] lock_acquire+0x1a9/0x500 [ 922.718266][ T300] lock_sock_nested+0x40/0xf0 [ 922.719325][ T300] strp_work+0x95/0x1e0 [ 922.720240][ T300] process_one_work+0xe28/0x1460 [ 922.721307][ T300] worker_thread+0x674/0xee0 [ 922.722283][ T300] kthread+0x3c3/0x760 [ 922.723101][ T300] ret_from_fork+0x46/0x80 [ 922.723792][ T300] ret_from_fork_asm+0x1a/0x30 [ 922.724532][ T300] [ 922.724532][ T300] -> #0 ((work_completion)(&strp->work)){+.+.}-{0:0}: [ 922.726038][ T300] check_prev_add+0x1af/0x2400 [ 922.726927][ T300] validate_chain+0xdcf/0x1a10 [ 922.727847][ T300] __lock_acquire+0xc4d/0x1ee0 [ 922.728721][ T300] lock_acquire+0x1a9/0x500 [ 922.729590][ T300] start_flush_work+0x41a/0xa50 [ 922.730434][ T300] __flush_work+0xee/0x210 [ 922.731213][ T300] cancel_work_sync+0xb8/0xd0 [ 922.732022][ T300] strp_done.cold+0x51/0xcf [ 922.732830][ T300] ovpn_tcp_socket_detach+0x28e/0x2de [ 922.733752][ T300] ovpn_socket_release_kref+0x1ef/0x350 [ 922.734713][ T300] ovpn_socket_release+0xe7/0x1a0 [ 922.735577][ T300] ovpn_peer_remove_work+0x2b/0x90 [ 922.736468][ T300] process_one_work+0xe28/0x1460 [ 922.737357][ T300] worker_thread+0x674/0xee0 [ 922.737985][ T300] kthread+0x3c3/0x760 [ 922.738545][ T300] ret_from_fork+0x46/0x80 [ 922.739177][ T300] ret_from_fork_asm+0x1a/0x30 [ 922.739846][ T300] [ 922.739846][ T300] other info that might help us debug this: [ 922.739846][ T300] [ 922.741159][ T300] Possible unsafe locking scenario: [ 922.741159][ T300] [ 922.742165][ T300] CPU0 CPU1 [ 922.743055][ T300] ---- ---- [ 922.743943][ T300] lock(sk_lock-AF_INET); [ 922.744638][ T300] lock((work_completion)(&strp->work)); [ 922.745786][ T300] lock(sk_lock-AF_INET); [ 922.746837][ T300] lock((work_completion)(&strp->work)); [ 922.747788][ T300] [ 922.747788][ T300] *** DEADLOCK *** [ 922.747788][ T300] [ 922.748856][ T300] 4 locks held by kworker/1:2/300: [ 922.749474][ T300] #0: ffff888008499b48 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0xd80/0x1460 [ 922.750588][ T300] #1: ffffc90002527d30 ((work_completion)(&peer->remove_work)){+.+.}-{0:0}, at: process_one_work+0xddf/0x1460 [ 922.751894][ T300] #2: ffff8880113edd98 (sk_lock-AF_INET){+.+.}-{0:0}, at: ovpn_socket_release+0x8a/0x1a0 [ 922.752983][ T300] #3: ffffffff854de980 (rcu_read_lock){....}-{1:3}, at: start_flush_work+0x39/0xa50 [ 922.754018][ T300] [ 922.754018][ T300] stack backtrace: [ 922.754734][ T300] CPU: 1 UID: 0 PID: 300 Comm: kworker/1:2 Tainted: G N 6.14.0-rc1-net-00276-g95f1f7ea224e-dirty #279 [ 922.754748][ T300] Tainted: [N]=TEST [ 922.754752][ T300] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Arch Linux 1.16.3-1-1 04/01/2014 [ 922.754761][ T300] Workqueue: events ovpn_peer_remove_work [ 922.754779][ T300] Call Trace: [ 922.754785][ T300] <TASK> [ 922.754791][ T300] dump_stack_lvl+0xa5/0x100 [ 922.754803][ T300] print_circular_bug.cold+0x38/0x48 [ 922.754820][ T300] check_noncircular+0x2f2/0x3d0 [ 922.754922][ T300] check_prev_add+0x1af/0x2400 [ 922.754942][ T300] validate_chain+0xdcf/0x1a10 [ 922.754991][ T300] __lock_acquire+0xc4d/0x1ee0 [ 922.755023][ T300] lock_acquire+0x1a9/0x500 [ 922.755104][ T300] start_flush_work+0x41a/0xa50 [ 922.755128][ T300] __flush_work+0xee/0x210 [ 922.755198][ T300] cancel_work_sync+0xb8/0xd0 [ 922.755211][ T300] strp_done.cold+0x51/0xcf [ 922.755222][ T300] ovpn_tcp_socket_detach+0x28e/0x2de [ 922.755237][ T300] ovpn_socket_release_kref+0x1ef/0x350 [ 922.755253][ T300] ovpn_socket_release+0xe7/0x1a0 [ 922.755268][ T300] ovpn_peer_remove_work+0x2b/0x90 [ 922.755282][ T300] process_one_work+0xe28/0x1460 [ 922.755330][ T300] worker_thread+0x674/0xee0 [ 922.755402][ T300] kthread+0x3c3/0x760 [ 922.755472][ T300] ret_from_fork+0x46/0x80 [ 922.755497][ T300] ret_from_fork_asm+0x1a/0x30 [ 922.755521][ T300] </TASK>
And then come the hung task warnings:
- del_peer waiting on the completion
- strp waiting on lock_sock
- peer cleanup/socket detach waiting on cancel_work_sync/strp
[ 1106.347400][ T39] INFO: task kworker/u16:0:11 blocked for more than 122 seconds. [ 1106.348547][ T39] Tainted: G N 6.14.0-rc1-net-00276-g95f1f7ea224e-dirty #279 [ 1106.349671][ T39] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1106.350748][ T39] task:kworker/u16:0 state:D stack:0 pid:11 tgid:11 ppid:2 task_flags:0x4208160 flags:0x00004000 [ 1106.352454][ T39] Workqueue: kstrp strp_work [ 1106.353133][ T39] Call Trace: [ 1106.353659][ T39] <TASK> [ 1106.354143][ T39] __schedule+0xace/0x2620 [ 1106.360659][ T39] schedule+0xd0/0x210 [ 1106.361266][ T39] __lock_sock+0x137/0x230 [ 1106.365430][ T39] lock_sock_nested+0xcb/0xf0 [ 1106.366173][ T39] strp_work+0x95/0x1e0 [ 1106.366845][ T39] process_one_work+0xe28/0x1460 [ 1106.369231][ T39] worker_thread+0x674/0xee0 [ 1106.371594][ T39] kthread+0x3c3/0x760 [ 1106.375692][ T39] ret_from_fork+0x46/0x80 [ 1106.377040][ T39] ret_from_fork_asm+0x1a/0x30 [ 1106.377851][ T39] </TASK> [ 1106.378355][ T39] INFO: task kworker/1:2:300 blocked for more than 122 seconds. [ 1106.379590][ T39] Tainted: G N 6.14.0-rc1-net-00276-g95f1f7ea224e-dirty #279 [ 1106.381079][ T39] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1106.382372][ T39] task:kworker/1:2 state:D stack:0 pid:300 tgid:300 ppid:2 task_flags:0x4208060 flags:0x00004000 [ 1106.384211][ T39] Workqueue: events ovpn_peer_remove_work [ 1106.385072][ T39] Call Trace: [ 1106.385648][ T39] <TASK> [ 1106.386139][ T39] __schedule+0xace/0x2620 [ 1106.393518][ T39] schedule+0xd0/0x210 [ 1106.394195][ T39] schedule_timeout+0x18c/0x240 [ 1106.398840][ T39] __wait_for_common+0x3e3/0x610 [ 1106.403079][ T39] __flush_work+0x14f/0x210 [ 1106.406874][ T39] cancel_work_sync+0xb8/0xd0 [ 1106.407519][ T39] strp_done.cold+0x51/0xcf [ 1106.408109][ T39] ovpn_tcp_socket_detach+0x28e/0x2de [ 1106.408851][ T39] ovpn_socket_release_kref+0x1ef/0x350 [ 1106.409588][ T39] ovpn_socket_release+0xe7/0x1a0 [ 1106.410271][ T39] ovpn_peer_remove_work+0x2b/0x90 [ 1106.410973][ T39] process_one_work+0xe28/0x1460 [ 1106.413075][ T39] worker_thread+0x674/0xee0 [ 1106.416968][ T39] kthread+0x3c3/0x760 [ 1106.419983][ T39] ret_from_fork+0x46/0x80 [ 1106.421172][ T39] ret_from_fork_asm+0x1a/0x30 [ 1106.421829][ T39] </TASK> [ 1106.422260][ T39] INFO: task ovpn-cli:1213 blocked for more than 122 seconds. [ 1106.423215][ T39] Tainted: G N 6.14.0-rc1-net-00276-g95f1f7ea224e-dirty #279 [ 1106.424451][ T39] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1106.425643][ T39] task:ovpn-cli state:D stack:0 pid:1213 tgid:1213 ppid:514 task_flags:0x400100 flags:0x00000002 [ 1106.427145][ T39] Call Trace: [ 1106.427610][ T39] <TASK> [ 1106.428005][ T39] __schedule+0xace/0x2620 [ 1106.431820][ T39] schedule+0xd0/0x210 [ 1106.432351][ T39] schedule_timeout+0x18c/0x240 [ 1106.435050][ T39] __wait_for_common+0x3e3/0x610 [ 1106.439809][ T39] ovpn_nl_peer_del_doit+0x270/0x6e0 [ 1106.442825][ T39] genl_family_rcv_msg_doit+0x1ea/0x2e0 [ 1106.445602][ T39] genl_family_rcv_msg+0x3a7/0x5b0 [ 1106.450559][ T39] genl_rcv_msg+0xb1/0x160 [ 1106.451154][ T39] netlink_rcv_skb+0x13e/0x3d0 [ 1106.455220][ T39] genl_rcv+0x29/0x40 [ 1106.455737][ T39] netlink_unicast+0x491/0x730 [ 1106.457107][ T39] netlink_sendmsg+0x77d/0xc00 [ 1106.458517][ T39] ____sys_sendmsg+0x7c5/0xac0 [ 1106.461329][ T39] ___sys_sendmsg+0x163/0x1b0 [ 1106.468146][ T39] __sys_sendmsg+0x135/0x1d0 [ 1106.471564][ T39] do_syscall_64+0x64/0x140 [ 1106.472173][ T39] entry_SYSCALL_64_after_hwframe+0x76/0x7e [ 1106.472947][ T39] RIP: 0033:0x7faa76628e56 [ 1106.473558][ T39] RSP: 002b:00007ffe757311e0 EFLAGS: 00000202 ORIG_RAX: 000000000000002e [ 1106.474674][ T39] RAX: ffffffffffffffda RBX: 00007faa7654f740 RCX: 00007faa76628e56 [ 1106.475715][ T39] RDX: 0000000000000000 RSI: 00007ffe75731270 RDI: 0000000000000003 [ 1106.476847][ T39] RBP: 00007ffe757311f0 R08: 0000000000000000 R09: 0000000000000000 [ 1106.477959][ T39] R10: 0000000000000000 R11: 0000000000000202 R12: 00005617490cf490 [ 1106.479064][ T39] R13: 00005617490d04f0 R14: 00007ffe75731270 R15: 0000561733d62d78 [ 1106.480175][ T39] </TASK> [ 1106.480646][ T39] INFO: lockdep is turned off.