openvpn icon indicating copy to clipboard operation
openvpn copied to clipboard

Published 20 hours ago • verified publisher icon OpenVPN

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

Open al1ta opened this issue 1 year ago • 3 comments

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

al1ta avatar Aug 07 '23 11:08 al1ta

The same problem with OpenVPN 2.4.7 under Ubuntu 22.04.

Socks proxy is provided by SSH:

ssh -D 1080 -N [email protected]`

It's normally accepted by curl:

curl -v -x socks5h://127.0.0.1:1080 http://showip.net/

But OpenVPN client fails with errno=115 "Operation now in progress".

When started with "proto udp" -- immediately:

Sat Sep  2 01:04:58 2023 us=326433 Attempting to establish TCP connection with [AF_INET]127.0.0.1:1080 [nonblock]
Sat Sep  2 01:04:58 2023 us=326597 TCP connection established with [AF_INET]127.0.0.1:1080
Sat Sep  2 01:04:58 2023 us=326981 recv_socks_reply: TCP port read failed on recv(): Operation now in progress (errno=115)
Sat Sep  2 01:04:58 2023 us=327050 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327118 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327148 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327179 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327228 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327255 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327285 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327311 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327339 TCP/UDP: Closing socket
Sat Sep  2 01:04:58 2023 us=327443 PID packet_id_free
Sat Sep  2 01:04:58 2023 us=327503 SIGUSR1[soft,init_instance] received, process restarting
Sat Sep  2 01:04:58 2023 us=327557 Restart pause, 5 second(s)

When started with "proto tcp" -- after 5 secs timeout:

Sat Sep  2 01:06:23 2023 us=795070 Attempting to establish TCP connection with [AF_INET]127.0.0.1:1080 [nonblock]
Sat Sep  2 01:06:23 2023 us=795242 TCP connection established with [AF_INET]127.0.0.1:1080
Sat Sep  2 01:06:28 2023 us=798481 recv_socks_reply: TCP port read timeout expired: Operation now in progress (errno=115)
Sat Sep  2 01:06:28 2023 us=798573 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798641 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798687 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798721 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798774 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798811 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798843 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798878 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=798921 TCP/UDP: Closing socket
Sat Sep  2 01:06:28 2023 us=799050 PID packet_id_free
Sat Sep  2 01:06:28 2023 us=799125 SIGUSR1[soft,init_instance] received, process restarting
Sat Sep  2 01:06:28 2023 us=799202 Restart pause, 5 second(s)

It's also discussed in https://community.openvpn.net/openvpn/ticket/328 since December 2013, but with no visible success(

ilyaevseev avatar Sep 01 '23 22:09 ilyaevseev

I was getting the same error with just the -D option, but the following seems to be working for me:

ssh -v -J [email protected] -D 8088 -N me@internal machine.name

(external is on the internet, and shares a local network with internal) Where I have an openvpn server on internal.machine.name with

remote external.machine.name

and I'm connecting from an openvpn client (on a machine running the ssh command above) that points at

socks-proxy 127.0.0.1 8088
socks-proxy-retry
remote internal machine.name

twshield avatar Feb 02 '24 22:02 twshield