OpenVPN / OpenVPN/openvpn

Suspected (very likely) bug in handling of socks-proxy setting when using UDP, results in connection loss and improper connection re-initialization (long connectivity loss periods)

Open
#379 7 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug
Dominant language
C
Stars
14.6k
Forks
3.4k
PR merge metrics
No merged PRs in 30d

Description

Describe the bug

I am running OpenVPN through a SOCKS proxy (UDP mode). The connection is established normally and runs okay for minutes to hours.
Periodically the connection tears down with timeout (I am fully confident it is not a network issue) and then OpenVPN attempts restart at which point it hangs for minutes.
After running it with high verbosity logs I found out that while the "hang" part consists of two stages

stage 1:
Logs do not show anomalies however the software communicating via OpenVPN's tun0 loses connectivity (timeout)

stage 2

For some reason, OpenVPN attempts to reconnect via TCP to the remote OpenVPN server (NOT THE SOCKS PROXY WHICH IS RUNNING ON LOCALHOST)

At this point it can spend minutes (unsuccessfully) trying to reach the remote server directly, finally concludes that network is unreachable and does full restart, which successfully restores connectivity

Here are the captured logs (exclamation marks added by me, interesting part also reproduced in github issue text below)


2023-08-02 20:50:17 us=37872 [se-mma-ovpn-018.mullvad.net] Inactivity timeout (--ping-restart), restarting
2023-08-02 20:50:17 us=50012 TCP/UDP: Closing socket
2023-08-02 20:50:17 us=50413 net_route_v4_del: 141.98.255.88/32 via 10.137.5.1 dev [NULL] table 0 metric -1
2023-08-02 20:50:17 us=50774 net_route_v4_del: 0.0.0.0/1 via 10.16.0.1 dev [NULL] table 0 metric -1
2023-08-02 20:50:17 us=50816 net_route_v4_del: 128.0.0.0/1 via 10.16.0.1 dev [NULL] table 0 metric -1
2023-08-02 20:50:17 us=50917 delete_route_ipv6(::/2)
2023-08-02 20:50:17 us=50929 net_route_v6_del: ::/2 via :: dev tun0 table 0 metric -1
2023-08-02 20:50:17 us=51010 delete_route_ipv6(4000::/2)
2023-08-02 20:50:17 us=51020 net_route_v6_del: 4000::/2 via :: dev tun0 table 0 metric -1
2023-08-02 20:50:17 us=51056 delete_route_ipv6(8000::/2)
2023-08-02 20:50:17 us=51067 net_route_v6_del: 8000::/2 via :: dev tun0 table 0 metric -1
2023-08-02 20:50:17 us=51103 delete_route_ipv6(c000::/2)
2023-08-02 20:50:17 us=51111 net_route_v6_del: c000::/2 via :: dev tun0 table 0 metric -1
2023-08-02 20:50:17 us=51149 Closing TUN/TAP interface
2023-08-02 20:50:17 us=51166 net_addr_v4_del: 10.16.0.3 dev tun0
2023-08-02 20:50:17 us=51544 net_addr_v6_del: fdda:d0d0:cafe:1302::1001/64 dev tun0
2023-08-02 20:50:17 us=57855 SIGUSR1[soft,ping-restart] received, process restarting
2023-08-02 20:50:17 us=59705 Restart pause, 1 second(s)
2023-08-02 20:50:18 us=62325 Re-using SSL/TLS context
2023-08-02 20:50:18 us=65480 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
2023-08-02 20:50:18 us=65513 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1450 tun_max_mtu:1600 headroom:136 payload:1800 tailroom:568 ET:32 ]
2023-08-02 20:50:18 us=65814 TCP/UDP: Preserving recently used remote address: [AF_INET]141.98.255.88:1302
2023-08-02 20:50:18 us=65856 Socket Buffers: R=[212992->425984] S=[212992->425984]
!!!!!!!!!!!!!!!
2023-08-02 20:55:11 us=65866 Attempting to establish TCP connection with [AF_INET]141.98.255.88:1302
!!!!!!!!!!!!
2023-08-02 20:55:11 us=66077 TCP: connect to [AF_INET]141.98.255.88:1302 failed: Network is unreachable
2023-08-02 20:55:11 us=66138 TCP/UDP: Closing socket
2023-08-02 20:55:11 us=66173 SIGUSR1[connection failed(soft),connection-failed] received, process restarting
2023-08-02 20:55:11 us=66259 Restart pause, 1 second(s)
2023-08-02 20:55:12 us=66354 Re-using SSL/TLS context
2023-08-02 20:55:12 us=66448 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
2023-08-02 20:55:12 us=66466 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1450 tun_max_mtu:1600 headroom:136 payload:1800 tailroom:568 ET:32 ]
2023-08-02 20:55:12 us=66499 TCP/UDP: Preserving recently used remote address: [AF_INET]127.0.0.1:2069
2023-08-02 20:55:12 us=66541 Socket Buffers: R=[212992->425984] S=[212992->425984]
2023-08-02 20:55:12 us=66550 Attempting to establish TCP connection with [AF_INET]127.0.0.1:2069
2023-08-02 20:55:12 us=66618 TCP connection established with [AF_INET]127.0.0.1:2069
2023-08-02 20:55:12 us=67384 SOCKS proxy wants us to send UDP to [AF_INET]127.0.0.1:2069
2023-08-02 20:55:12 us=67401 NOTE: setsockopt TCP_NODELAY=1 failed
2023-08-02 20:55:12 us=67414 UDPv4 link local: (not bound)
2023-08-02 20:55:12 us=67423 UDPv4 link remote: [AF_INET]185.213.154.138:1302
2023-08-02 20:55:13 us=58053 TLS: Initial packet from [AF_INET]185.213.154.138:1302, sid=56293a44 16504030
2023-08-02 20:55:13 us=105546 VERIFY OK: depth=2, C=SE, ST=Gotaland, L=Gothenburg, O=Amagicom AB, OU=Mullvad, CN=Mullvad Root CA v2, emailAddress=security@mullvad.net

To Reproduce
Start OpenVPN in UDP mode with SOCKS5 enabled (socks-proxy in config, so socks proxy must support UDP. Ideally it should be on localhost since in my setup it is)

Run it for a while, with moderate load.

P.S.
Upon further experiments I discovered that the "strange attempt to bypass socks proxy" also happens upon "normal" connectivity loss events (turning off the wifi router to which the machine with VPN client is connected, waiting for timeout then turning on)

Expected behavior
Everything to work without weird connectivity losses when there is no good reason for connectivity loss.

If a connectivity loss happens for normal reasons (such as physical connection getting temporarily disconnected) do not perform useless attempt to connect to remote server bypassing the socks proxy and re-connect to socks proxy (which it eventually does but only after very long wait), when socks proxy option is set the re-connect attempt should be performed to the socks proxy
(and not to the last remembered remote OpenVPN server as it appears to attempt in log above)

Version information (please complete the following information):

  • OS: Debian 11 (bare metal and VM), Debian 10 (VM), Fedora (VM) (issue reproduced on all)

Tested on two following OpenVPN versions (reproduces):

OpenVPN 2.4.7 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 28 2021
library versions: OpenSSL 1.1.1n 15 Mar 2022, LZO 2.10

OpenVPN 2.6.5 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] [DCO]
library versions: OpenSSL 3.1.1 30 May 2023, LZO 2.10

Additional context
Socks capability is why I'm using openvpn in the first place so any suggestion on how to work around this would be extremely welcome

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by reproducing the UDP SOCKS5 setup described in the issue and compare the captured reconnect logs, especially the direct TCP attempt to the remote server versus the later SOCKS proxy connection. The change is done when reconnects with socks-proxy configured do not bypass the proxy and restore connectivity without the long delay.

Written by the indexing model from the issue text.

Assessment

Tech stack
c
Domain
networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.