Page 1 of 1

OpenVPN over UDP stopped working for some clients

Posted: Fri Apr 07, 2017 10:52 am
by tsa_akis
Hello,

I have a frustrating TLS error problem since a few days, where some clients can connect to my OpenVPN server and some cannot. It's running on Windows using UDP/1194 and all the clients have exact same settings. I am attaching a server log level 6 of a working client and one not working. I don't have access to the not working client log (it's remote).

In addition, this exact setup used to work for long time (more than a year) until it stopped on the 4th April 2017.

It seems like the client can reach the server but the server cannot reply back to the client. BUT this only happens for some of the clients, even ones that belong to the same public network (in remote areas). So I cannot imagine how it can be a firewall error.

NOT WORKING

Code: Select all

Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 Re-using SSL/TLS context
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 LZO compression initialized
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 Local Options hash (VER=V4): 'a8f55717'
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 Expected Remote Options hash (VER=V4): '22188c5b'
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 UDPv4 READ [14] from [AF_INET]bad_client:49003: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 TLS: Initial packet from [AF_INET]bad_client:49003, sid=7ea5008f ee298f22
Fri Apr 07 09:51:38 2017 us=278366 bad_client:49003 UDPv4 WRITE [26] to [AF_INET]bad_client:49003: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0

Fri Apr 07 09:51:40 2017 us=310517 bad_client:49003 UDPv4 WRITE [14] to [AF_INET]bad_client:49003: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0

Fri Apr 07 09:51:44 2017 us=374822 bad_client:49003 UDPv4 WRITE [14] to [AF_INET]bad_client:49003: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0

Fri Apr 07 09:51:52 2017 us=503448 bad_client:49003 UDPv4 WRITE [14] to [AF_INET]bad_client:49003: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0

Fri Apr 07 09:52:08 2017 us=791909 bad_client:49003 UDPv4 WRITE [14] to [AF_INET]bad_client:49003: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0

Fri Apr 07 09:52:39 2017 us=87018 bad_client:49003 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Fri Apr 07 09:52:39 2017 us=87018 bad_client:49003 TLS Error: TLS handshake failed
Fri Apr 07 09:52:39 2017 us=87018 bad_client:49003 SIGUSR1[soft,tls-error] received, client-instance restarting

Fri Apr 07 09:52:39 2017 us=399300 MULTI: multi_create_instance called
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 Re-using SSL/TLS context
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 LZO compression initialized
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 Local Options hash (VER=V4): 'a8f55717'
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 Expected Remote Options hash (VER=V4): '22188c5b'
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 UDPv4 READ [14] from [AF_INET]bad_client:49004: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 TLS: Initial packet from [AF_INET]bad_client:49004, sid=3850de6b eadae20a
Fri Apr 07 09:52:39 2017 us=399300 bad_client:49004 UDPv4 WRITE [26] to [AF_INET]bad_client:49004: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Fri Apr 07 09:52:41 2017 us=775314 bad_client:49004 UDPv4 WRITE [14] to [AF_INET]bad_client:49004: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0
Fri Apr 07 09:52:45 2017 us=292476 bad_client:49004 UDPv4 WRITE [14] to [AF_INET]bad_client:49004: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0

WORKING

Code: Select all

Fri Apr 07 09:51:46 2017 us=109968 MULTI: multi_create_instance called
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 Re-using SSL/TLS context
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 LZO compression initialized
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 Local Options hash (VER=V4): 'a8f55717'
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 Expected Remote Options hash (VER=V4): '22188c5b'
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 UDPv4 READ [14] from [AF_INET]good_client:62320: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 TLS: Initial packet from [AF_INET]good_client:62320, sid=0a4a2388 525f8203
Fri Apr 07 09:51:46 2017 us=109968 good_client:62320 UDPv4 WRITE [26] to [AF_INET]good_client:62320: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Fri Apr 07 09:51:46 2017 us=156863 good_client:62320 UDPv4 READ [22] from [AF_INET]good_client:62320: P_ACK_V1 kid=0 [ 0 ]
Fri Apr 07 09:51:46 2017 us=156863 good_client:62320 UDPv4 READ [114] from [AF_INET]good_client:62320: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=100
Fri Apr 07 09:51:46 2017 us=156863 good_client:62320 UDPv4 WRITE [22] to [AF_INET]good_client:62320: P_ACK_V1 kid=0 [ 1 ]
Fri Apr 07 09:51:46 2017 us=156863 good_client:62320 UDPv4 READ [114] from [AF_INET]good_client:62320: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=100
Fri Apr 07 09:51:46 2017 us=156863 good_client:62320 UDPv4 WRITE [22] to [AF_INET]good_client:62320: P_ACK_V1 kid=0 [ 2 ]

As you can see, the P_ACK_V1 that is sent back to the server by the second client, is never sent by the first client. So it tries to complete the handshake forever...

I searched through the forum and found some old similar topics. I tried the following idea on the server config, but didn't help (viewtopic.php?t=21519)

local xxx.xxx.xxx.xxx

Any ideas how to troubleshoot this? Could it be a networking/routing problem? Thanks so much for reading through!

Re: OpenVPN over UDP stopped working for some clients

Posted: Tue Apr 11, 2017 10:12 am
by tsa_akis
Just for the sake of completeness, this was neither a networking/firewall issue nor OpenVPN configuration. Just some of the clients (connected via prepaid 3G) did not have enough balance...

The twist is that the outgoing packets from the client could reach the server, but the incoming packets from the server could not reach the client. I guess the low balance limitation was only on downloading.

Re: OpenVPN over UDP stopped working for some clients

Posted: Tue Apr 11, 2017 10:22 am
by TinCanTech
Thanks for letting us know 8-)

Re: OpenVPN over UDP stopped working for some clients

Posted: Wed Apr 12, 2017 12:39 pm
by tsa_akis
Another question on the same issue.

This is the client log from a remote device running BusyBox and connected via 3G/UMTS. Log level should be 3.
The device retries to connect every minute and fails (timeout), then a minute later it succeeds just like that, no change in configuration.

CLIENT LOG

Code: Select all

Apr 12 10:47:29 ovpn-tunnel1[1155]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 12 10:47:29 ovpn-tunnel1[1155]: TLS Error: TLS handshake failed
Apr 12 10:47:29 ovpn-tunnel1[1155]: SIGUSR1[soft,tls-error] received, process restarting
Apr 12 10:47:29 ovpn-tunnel1[1155]: Restart pause, 2 second(s)

# FAIL
Apr 12 10:47:31 ovpn-tunnel1[1155]: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Apr 12 10:47:31 ovpn-tunnel1[1155]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 12 10:47:31 ovpn-tunnel1[1155]: Socket Buffers: R=[110592->131072] S=[110592->131072]
Apr 12 10:47:31 ovpn-tunnel1[1155]: UDPv4 link local: [undef]
Apr 12 10:47:31 ovpn-tunnel1[1155]: UDPv4 link remote: vpn_server:1194
Apr 12 10:47:31 ovpn-tunnel1[1155]: TLS: Initial packet from vpn_server:1194, sid=82723ca5 ddf47e6b
Apr 12 10:47:36 gsmCtrld[754]: packet service type changed to HSDPA/HSUPA
Apr 12 10:47:47 gsmCtrld[754]: packet service type changed to UMTS
Apr 12 10:48:31 ovpn-tunnel1[1155]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 12 10:48:31 ovpn-tunnel1[1155]: TLS Error: TLS handshake failed
Apr 12 10:48:31 ovpn-tunnel1[1155]: SIGUSR1[soft,tls-error] received, process restarting
Apr 12 10:48:31 ovpn-tunnel1[1155]: Restart pause, 2 second(s)

# SUCCESS
Apr 12 10:48:33 ovpn-tunnel1[1155]: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Apr 12 10:48:33 ovpn-tunnel1[1155]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 12 10:48:33 ovpn-tunnel1[1155]: Socket Buffers: R=[110592->131072] S=[110592->131072]
Apr 12 10:48:33 ovpn-tunnel1[1155]: UDPv4 link local: [undef]
Apr 12 10:48:33 ovpn-tunnel1[1155]: UDPv4 link remote: vpn_server:1194
Apr 12 10:48:33 ovpn-tunnel1[1155]: TLS: Initial packet from vpn_server:1194, sid=a724647f 246c02f5
Apr 12 10:48:36 ovpn-tunnel1[1155]: VERIFY OK: depth=1, C=DE, ...
Apr 12 10:48:36 ovpn-tunnel1[1155]: VERIFY OK: depth=0, C=DE, ...
Apr 12 10:48:39 ovpn-tunnel1[1155]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Apr 12 10:48:39 ovpn-tunnel1[1155]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Apr 12 10:48:39 ovpn-tunnel1[1155]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Apr 12 10:48:39 ovpn-tunnel1[1155]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Apr 12 10:48:39 ovpn-tunnel1[1155]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Apr 12 10:48:39 ovpn-tunnel1[1155]: [server] Peer Connection Initiated with vpn_server:1194
Apr 12 10:48:41 gsmCtrld[754]: packet service type changed to HSDPA/HSUPA
Could it be that the network signal is quite poor, causing the timeouts? -93dBm at best, down to -107dBm.

Also this FAQ does not seem to help in this case
https://openvpn.net/index.php/open-sour ... ivity.html


Side question: Another client that successfully connects, logs UDPv4 link local (bound): [undef]. Any idea what that bound means?