DCO and TCP leading to instance hangs

[cron2]

This is still a bit vague, to collect information

commit cb8a0f6 running on ubuntu 20.04 with backport, sometimes TCP instances get "stuck"

This is a multisocket server that has 2x UDP and 1x TCP socket, and 1 TCP client

2025-07-18 19:00:58 us=392489 tcp6-server:194.97.140.5:34849 peer-id=16777215 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
2025-07-18 19:00:58 us=392701 tcp6-server:194.97.140.5:34849 peer-id=16777215 TLS: tls_multi_process: initial untrusted session promoted to trusted
2025-07-18 19:00:58 us=392885 tcp6-server:194.97.140.5:34849 peer-id=16777215 TCPv6_SERVER WRITE [196] to [AF_INET6]::ffff:194.97.140.5:34849: P_CONTROL_V1 kid=0 [ 4 3 2 1 ] pid=4 DATA len=158
2025-07-18 19:00:58 us=393128 tcp6-server:194.97.140.5:34849 peer-id=16777215 TCPv6_SERVER WRITE [247] to [AF_INET6]::ffff:194.97.140.5:34849: P_CONTROL_V1 kid=0 [ 4 3 2 1 ] pid=5 DATA len=209
2025-07-18 19:00:58 us=437966 tcp6-server:194.97.140.5:34849 peer-id=16777215 TCPv6_SERVER READ [34] from [AF_INET6]::ffff:194.97.140.5:34849: P_ACK_V1 kid=0 [ 4 3 2 1 ] DATA len=0
2025-07-18 19:00:58 us=438807 tcp6-server:194.97.140.5:34849 peer-id=16777215 TCPv6_SERVER READ [34] from [AF_INET6]::ffff:194.97.140.5:34849: P_ACK_V1 kid=0 [ 5 4 3 2 ] DATA len=0
2025-07-18 19:00:58 us=439198 tcp6-server:194.97.140.5:34849 peer-id=16777215 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bits RSA, signature: RSA-SHA256, peer temporary key: 253 bits X25519, peer signing digest/type: SHA256 RSASSA-PSS
2025-07-18 19:00:58 us=439529 tcp6-server:194.97.140.5:34849 peer-id=16777215 [freebsd-14-amd64] Peer Connection Initiated with [AF_INET6]::ffff:194.97.140.5:34849
2025-07-18 19:00:58 us=439869 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 MULTI_sva: pool returned IPv4=10.220.2.4, IPv6=fd00:abcd:220:2::1002
2025-07-18 19:00:58 us=440323 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 OPTIONS IMPORT: reading client specific options from: ccd/freebsd-14-amd64
2025-07-18 19:00:58 us=440734 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 dco_new_peer: peer-id 1, fd 10, remote addr: [undefined]
2025-07-18 19:00:58 us=441009 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 Data Channel MTU parms [ mss_fix:1368 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2025-07-18 19:00:58 us=441224 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 Outgoing dynamic tls-crypt: Cipher 'AES-256-CTR' initialized with 256 bit key
2025-07-18 19:00:58 us=441423 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 Outgoing dynamic tls-crypt: Using 256 bit message hash 'SHA256' for HMAC authentication
2025-07-18 19:00:58 us=441588 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 Incoming dynamic tls-crypt: Cipher 'AES-256-CTR' initialized with 256 bit key
2025-07-18 19:00:58 us=441763 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 Incoming dynamic tls-crypt: Using 256 bit message hash 'SHA256' for HMAC authentication
2025-07-18 19:00:58 us=441938 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 dco_set_peer: peer-id 1, keepalive 10/60, mss 1368
2025-07-18 19:00:58 us=442250 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 dco_install_key: peer_id=1 keyid=0, currently 0 keys installed
2025-07-18 19:00:58 us=442413 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 dco_new_key: slot 0, key-id 0, peer-id 1, cipher AES-256-GCM
2025-07-18 19:00:58 us=442679 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 MULTI: Learn: 10.220.2.4 -> freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1
2025-07-18 19:00:58 us=442848 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 MULTI: primary virtual IP for freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1: 10.220.2.4
2025-07-18 19:00:58 us=443022 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 MULTI: Learn: fd00:abcd:220:2::1002 -> freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1
2025-07-18 19:00:58 us=443186 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 MULTI: primary virtual IPv6 for freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1: fd00:abcd:220:2::1002
2025-07-18 19:00:58 us=443394 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 SENT CONTROL [freebsd-14-amd64]: 'PUSH_REPLY,route 10.220.0.0 255.255.0.0,route-ipv6 fd00:abcd:220::/48,tun-ipv6,route-gateway 10.220.2.1,topology subnet,ping 10,ping-restart 30,compress stub-v2,ifconfig-ipv6 fd00:abcd:220:2::1002/64 fd00:abcd:220:2::1,ifconfig 10.220.2.4 255.255.255.0,peer-id 1,cipher AES-256-GCM,protocol-flags cc-exit tls-ekm dyn-tls-crypt,tun-mtu 1500' (status=1)
2025-07-18 19:00:58 us=443623 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 TCPv6_SERVER WRITE [400] to [AF_INET6]::ffff:194.97.140.5:34849: P_CONTROL_V1 kid=0 [ 4 3 2 1 ] pid=6 DATA len=362
^C

at this point, the instance is dead. Ctrl-C does not do anything, strace shows

gert@ubuntu2004:~$ SU strace -p 1061185
strace: Process 1061185 attached
recvfrom(10, 

so I guess it got told "there is something to read on the TCP socket" but the kernel ate it away? Concurrent pings on the TCP socket work fine (kernel handling data channel), but the userland instance never(?) recovers (maybe a reneg initiated by the other side would help). If I kill the TCP client...

^C2025-07-18 19:06:31 us=729181 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 register signal: SIGUSR1 (connection-reset)
2025-07-18 19:06:31 us=731325 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 Connection reset, restarting [0]
2025-07-18 19:06:31 us=732254 freebsd-14-amd64/tcp6-server:194.97.140.5:34849 peer-id=1 SIGUSR1[soft,connection-reset] received, client-instance restarting
2025-07-18 19:06:31 us=733258 dco_get_peer_stats_multi
2025-07-18 19:06:31 us=746961 dco_parse_peer_multi: parsing message...
2025-07-18 19:06:31 us=747793 dco_update_peer_stat: no link RX bytes provided in reply for peer 0
2025-07-18 19:06:31 us=749217 dco_update_peer_stat: no link TX bytes provided in reply for peer 0
2025-07-18 19:06:31 us=749871 dco_update_peer_stat: no VPN RX bytes provided in reply for peer 0
2025-07-18 19:06:31 us=750464 dco_update_peer_stat: no VPN TX bytes provided in reply for peer 0
2025-07-18 19:06:31 us=751781 dco_parse_peer_multi: parsing message...
2025-07-18 19:06:31 us=752568 dco_parse_peer_multi: cannot store DCO stats for peer 1
2025-07-18 19:06:31 us=754087 register signal: SIGTERM (close_context)
2025-07-18 19:06:31 us=755089 dco_del_peer: peer-id 1
2025-07-18 19:06:31 us=775588 Sent warning SSL alert: close notify
2025-07-18 19:06:31 us=777506 TCP/UDP: Closing socket
2025-07-18 19:06:31 us=783559 dco_get_peer_stats_multi
2025-07-18 19:06:31 us=784921 register signal: SIGTERM (close_context)
2025-07-18 19:06:31 us=785427 dco_del_peer: peer-id 0
2025-07-18 19:06:31 us=786761 kernel error: ovpn: cannot find peer with id 0
2025-07-18 19:06:31 us=787263 dco_del_peer: netlink reports object not found, ovpn-dco unloaded?
2025-07-18 19:06:31 us=787798 dco_del_peer: failed to send netlink message: No such file or directory (-2)
2025-07-18 19:06:31 us=788473 Sent warning SSL alert: close notify
2025-07-18 19:06:31 us=789365 TCP/UDP: Closing socket
2025-07-18 19:06:31 us=790171 TCP/UDP: Closing socket
2025-07-18 19:06:31 us=790762 TCP/UDP: Closing socket

the ctrl-c registers (and, I think, I see a DCO notification mixup, but that is not the root cause) and the server exits.

[cron2]

This is fully reproduceable - I'm trying to test gerrit#1078 so this is highly getting in the way :-)

A client-side reneg-sec TLS soft reset will not be sufficient to unlock this...

2025-07-18 19:12:21 Protocol options: protocol-flags cc-exit tls-ekm dyn-tls-crypt
2025-07-18 19:13:21 TLS: soft reset sec=60/60 bytes=956/-1 pkts=15/0 aead_limit_send=51/60129542137 aead_limit_recv=15/60129542137
2025-07-18 19:14:22 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
2025-07-18 19:14:22 TLS Error: TLS handshake failed

(client side). When this happens the server unlocks, and I can see activity in strace

write(1, "2025-07-18 19:16:25 us=347430 fr"..., 487) = 487
epoll_ctl(9, EPOLL_CTL_MOD, 6, {EPOLLIN, {u32=1635806192, u64=94705664682992}}) = 0
epoll_ctl(9, EPOLL_CTL_MOD, 7, {EPOLLIN, {u32=1635806624, u64=94705664683424}}) = 0
epoll_ctl(9, EPOLL_CTL_MOD, 8, {EPOLLIN, {u32=1635807056, u64=94705664683856}}) = 0
epoll_ctl(9, EPOLL_CTL_MOD, 5, {EPOLLIN, {u32=6, u64=6}}) = 0
epoll_wait(9, [], 1029, 0)              = 0
poll([{fd=10, events=POLLOUT}], 1, 0)   = 1 ([{fd=10, revents=POLLOUT}])
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2326, ...}) = 0
write(1, "2025-07-18 19:16:25 us=349691 fr"..., 220) = 220
sendto(10, "\1\220 \364\306<n]\212\tR\4\0\0\0\4\0\0\0\3\0\0\0\2\0\0\0\1\376\341\364\363"..., 402, MSG_NOSIGNAL, NULL, 0) = 402
epoll_ctl(9, EPOLL_CTL_MOD, 6, {EPOLLIN, {u32=1635806192, u64=94705664682992}}) = 0
epoll_ctl(9, EPOLL_CTL_MOD, 7, {EPOLLIN, {u32=1635806624, u64=94705664683424}}) = 0
epoll_ctl(9, EPOLL_CTL_MOD, 8, {EPOLLIN, {u32=1635807056, u64=94705664683856}}) = 0
epoll_ctl(9, EPOLL_CTL_MOD, 5, {EPOLLIN, {u32=6, u64=6}}) = 0
epoll_wait(9, [{EPOLLIN, {u32=1636127472, u64=94705665004272}}], 1029, 1177) = 1
recvfrom(10, 

(and then it hangs again, until the next client TCP disconnect)

gert@ubuntu2004:~$ SU lsof -i |grep openvpn
openvpn   1061229          nobody    6u  IPv6 42199310      0t0  UDP *:51194 
openvpn   1061229          nobody    7u  IPv4 42199311      0t0  UDP *:51294 
openvpn   1061229          nobody    8u  IPv6 42199312      0t0  TCP *:51294 (LISTEN)
openvpn   1061229          nobody   10u  IPv6 42199386      0t0  TCP ubuntu2004.ov.greenie.net:51294->fbsd14.ov.greenie.net:41754 (ESTABLISHED)

so that's just "the client socket on fd 10"...