openvpn doesn't connect to socks5 proxy : recv_socks_reply: TCP port read timeout expired: Operation now in progress (errno=115)

Hi,

I'm using openvpn-2.6.5-1.fc38.x86_64 but I tried with ubuntu and debian ones

I'm trying to connect openvpn trough socks5 proxy
and I get this error at startup

recv_socks_reply: TCP port read timeout expired: Operation now in progress (errno=115)

from the same openvpn node the proxy it is working since checked by curl

curl -sL --socks5-hostname  $SOCKSV5HOST:$SOCKSV5PORT http://www.showip.com

here the openvpn params:

exec openvpn --config vpnconfigfile.conf \
  --redirect-gateway local \
  --user nobody --group nobody \
  --auth-user-pass /tmp/credentials --socks-proxy $SOCKSV5HOST $SOCKSV5PORT --socks-proxy-retry --mtu-disc yes --verb 21

here the full logs

2023-08-06 13:32:56 us=319814 PID packet_id_free
2023-08-06 13:32:56 us=319859 PID packet_id_free
2023-08-06 13:32:56 us=319872 PID packet_id_free
2023-08-06 13:32:56 us=319880 PID packet_id_free
2023-08-06 13:32:56 us=319902 PID packet_id_free
2023-08-06 13:32:56 us=319912 PID packet_id_free
2023-08-06 13:32:56 us=319921 PID packet_id_free
2023-08-06 13:32:56 us=319930 PID packet_id_free
2023-08-06 13:32:56 us=319948 TCP/UDP: Closing socket
2023-08-06 13:32:56 us=320076 PID packet_id_free
2023-08-06 13:32:56 us=320134 SIGUSR1[soft,socks-error] received, process restarting
2023-08-06 13:32:56 us=320183 Restart pause, 2 second(s)
2023-08-06 13:32:58 us=320692 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2023-08-06 13:32:58 us=320748 NOTE: --fast-io is disabled since we are not using UDP
2023-08-06 13:32:58 us=320761 PO_INIT maxevents=5 flags=0x00000002
2023-08-06 13:32:58 us=320771 Re-using SSL/TLS context
2023-08-06 13:32:58 us=320797 LZO compression initializing
2023-08-06 13:32:58 us=320809 MTU: adding 426 buffer tailroom for compression for 1768 bytes of payload
2023-08-06 13:32:58 us=320818 TLS: tls_session_init: entry
2023-08-06 13:32:58 us=320848 PID packet_id_init seq_backtrack=64 time_backtrack=15
2023-08-06 13:32:58 us=320902 PID packet_id_init seq_backtrack=64 time_backtrack=15
2023-08-06 13:32:58 us=320918 TLS: tls_session_init: new session object, sid=8778615b d6d97c01
2023-08-06 13:32:58 us=320927 TLS: tls_session_init: entry
2023-08-06 13:32:58 us=320942 PID packet_id_init seq_backtrack=64 time_backtrack=15
2023-08-06 13:32:58 us=320978 PID packet_id_init seq_backtrack=64 time_backtrack=15
2023-08-06 13:32:58 us=320995 TLS: tls_session_init: new session object, sid=5b9dddca d056ba17
2023-08-06 13:32:58 us=321018 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-06 13:32:58 us=321054 RESOLVE_REMOTE flags=0x0101 phase=1 rrs=0 sig=-1 status=0
2023-08-06 13:32:58 us=321079 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2023-08-06 13:32:58 us=321217 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,auth SHA1,keysize 256,key-method 2,tls-client'
2023-08-06 13:32:58 us=321244 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,auth SHA1,keysize 256,key-method 2,tls-server'
2023-08-06 13:32:58 us=321268 STREAM: RESET
2023-08-06 13:32:58 us=321284 STREAM: INIT maxlen=1768
2023-08-06 13:32:58 us=321310 TCP/UDP: Preserving recently used remote address: [AF_INET]10.89.1.7:9050
2023-08-06 13:32:58 us=321458 Socket Buffers: R=[131072->131072] S=[16384->16384]
2023-08-06 13:32:58 us=321495 Attempting to establish TCP connection with [AF_INET]10.89.1.7:9050
2023-08-06 13:32:58 us=321707 TCP connection established with [AF_INET]10.89.1.7:9050
2023-08-06 13:33:03 us=327511 recv_socks_reply: TCP port read timeout expired: Operation now in progress (errno=115)

here the tcpdumps from the connection.

    4   8.001288   10.89.0.90 → 10.89.0.89   TCP 74 45792 → 9050 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM TSval=4046296586 TSecr=0 WS=128
    5   8.001328   10.89.0.89 → 10.89.0.90   TCP 74 9050 → 45792 [SYN, ACK] Seq=0 Ack=1 Win=65160 Len=0 MSS=1460 SACK_PERM TSval=3323323275 TSecr=4046296586 WS=128
    6   8.001364   10.89.0.90 → 10.89.0.89   TCP 66 45792 → 9050 [ACK] Seq=1 Ack=1 Win=64256 Len=0 TSval=4046296586 TSecr=3323323275
    7   8.001467   10.89.0.90 → 10.89.0.89   TCP 69 45792 → 9050 [PSH, ACK] Seq=1 Ack=1 Win=64256 Len=3 TSval=4046296586 TSecr=3323323275
    8   8.001476   10.89.0.89 → 10.89.0.90   TCP 66 9050 → 45792 [ACK] Seq=1 Ack=4 Win=65280 Len=0 TSval=3323323275 TSecr=4046296586
    9   8.001594   10.89.0.89 → 10.89.0.90   TCP 68 9050 → 45792 [PSH, ACK] Seq=1 Ack=4 Win=65280 Len=2 TSval=3323323275 TSecr=4046296586
   10   8.001668   10.89.0.90 → 10.89.0.89   TCP 66 45792 → 9050 [ACK] Seq=4 Ack=3 Win=64256 Len=0 TSval=4046296586 TSecr=3323323275
   11   8.001715   10.89.0.90 → 10.89.0.89   TCP 88 45792 → 9050 [PSH, ACK] Seq=4 Ack=3 Win=64256 Len=22 TSval=4046296587 TSecr=3323323275
   12   8.042771   10.89.0.89 → 10.89.0.90   TCP 66 9050 → 45792 [ACK] Seq=3 Ack=26 Win=65280 Len=0 TSval=3323323317 TSecr=4046296587
   13  13.006994   10.89.0.90 → 10.89.0.89   TCP 66 45792 → 9050 [FIN, ACK] Seq=26 Ack=3 Win=64256 Len=0 TSval=4046301592 TSecr=3323323317
   14  13.007226   10.89.0.89 → 10.89.0.90   TCP 66 9050 → 45792 [FIN, ACK] Seq=3 Ack=27 Win=65280 Len=0 TSval=3323328281 TSecr=4046301592

Cheers

Start by reproducing the SOCKS5 connection with the shown openvpn command and configuration, then trace the handling associated with recv_socks_reply against the supplied log and tcpdump. Done means the SOCKS5 handshake completes and OpenVPN establishes its connection without the timeout.