Windows fails to connect

stinga@wolf-rock.com

G'day all,

This doing my head in :-)

openvpn was working fine on a laptop, we believe a windows update was done and now openvpn fails to connect and gets the error

Sun Jun 07 09:07:02 2020 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sun Jun 07 09:07:02 2020 TLS Error: TLS handshake failed

Lots of reading suggest the network is unavailable (or various network related issues)
I am using TeamViewer to connect to the remote laptop so the network is good.

This is a home setup in the UK, there is another linux box that uses different connection details to connect to the same server and it has no issues at all.

I have not had the person test at another location, to eliminate their home setup as the issue, but will try and get them to do that.

Windows 10 Home Version:1903

OpenVPN 2.4.9 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Apr 16 2020

We have reinstalled openvpn.
We have removed the tap driver, uninstalled openvpn and reinstalled openvpn.
We have removed just the tap driver and downloaded and reinstalled tap-windows-9.21.2.exe from https://swupdate.openvpn.org/community/releases/tap-windows-9.21.2.exe

In "Network Connections" "Ethernet 2" is the TAP Adaptor v9, but it shows a red x and states "Networl cable unplugged", I don't have another windows box to see if that is normal, but I suspect it maybe related to the issue.

Any thoughts or other things I can look at?

Thanks!

TinCanTech

stinga@wolf-rock.com wrote Any thoughts or other things I can look at?

The server log.

https://forums.openvpn.net/viewtopic.php?f=30&t=22603

stinga@wolf-rock.com

Pretty much the same thing...

Jun  7 23:29:28 cf-fw openvpnserver[18095]: 94.9.29.181:34986 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Jun  7 23:29:28 cf-fw openvpnserver[18095]: 94.9.29.181:34986 TLS Error: TLS handshake failed
Jun  7 23:29:28 cf-fw openvpnserver[18095]: 94.9.29.181:34986 SIGUSR1[soft,tls-error] received, client-instance restarting
Jun  7 23:29:33 cf-fw openvpnserver[18095]: 94.9.29.181:38966 TLS: Initial packet from [AF_INET]94.9.29.181:38966, sid=27320c5e 53740159
Jun  7 23:30:34 cf-fw openvpnserver[18095]: 94.9.29.181:38966 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Jun  7 23:30:34 cf-fw openvpnserver[18095]: 94.9.29.181:38966 TLS Error: TLS handshake failed
Jun  7 23:30:34 cf-fw openvpnserver[18095]: 94.9.29.181:38966 SIGUSR1[soft,tls-error] received, client-instance restarting
Jun  7 23:30:38 cf-fw openvpnserver[18095]: 94.9.29.181:35909 TLS: Initial packet from [AF_INET]94.9.29.181:35909, sid=76805d91 433354af
Jun  7 23:31:38 cf-fw openvpnserver[18095]: 94.9.29.181:35909 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Jun  7 23:31:38 cf-fw openvpnserver[18095]: 94.9.29.181:35909 TLS Error: TLS handshake failed
Jun  7 23:31:38 cf-fw openvpnserver[18095]: 94.9.29.181:35909 SIGUSR1[soft,tls-error] received, client-instance restarting
Jun  7 23:31:43 cf-fw openvpnserver[18095]: 94.9.29.181:54159 TLS: Initial packet from [AF_INET]94.9.29.181:54159, sid=97ead9b3 6128d84b
Jun  7 23:32:44 cf-fw openvpnserver[18095]: 94.9.29.181:54159 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Only on verb 3I have increased to 4 and will update when I have more detailed logs.

stinga@wolf-rock.com

Now my Debian box is showing the same symptoms. (hopefully that will be easier to diagnose)

Linux shark 4.9.0-12-amd64 #1 SMP Debian 4.9.210-1 (2020-01-20) x86_64 GNU/Linux

Client log

Mon Jun  8 15:02:09 2020 us=396945 OpenVPN 2.4.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Oct 14 2018
Mon Jun  8 15:02:09 2020 us=396953 library versions: OpenSSL 1.0.2u  20 Dec 2019, LZO 2.08
Mon Jun  8 15:02:09 2020 us=397267 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Mon Jun  8 15:02:09 2020 us=397757 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Mon Jun  8 15:02:11 2020 us=354983 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Mon Jun  8 15:02:11 2020 us=355177 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Mon Jun  8 15:02:11 2020 us=355232 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Mon Jun  8 15:02:11 2020 us=356181 TCP/UDP: Preserving recently used remote address: [AF_INET]80.229.131.73:1194
Mon Jun  8 15:02:11 2020 us=356269 Socket Buffers: R=[212992->212992] S=[212992->212992]
Mon Jun  8 15:02:11 2020 us=356296 UDP link local: (not bound)
Mon Jun  8 15:02:11 2020 us=356322 UDP link remote: [AF_INET]80.229.131.73:1194
Mon Jun  8 15:02:11 2020 us=356350 NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Mon Jun  8 15:03:11 2020 us=200776 [UNDEF] Inactivity timeout (--ping-restart), restarting
Mon Jun  8 15:03:11 2020 us=201012 TCP/UDP: Closing socket
Mon Jun  8 15:03:11 2020 us=201098 SIGUSR1[soft,ping-restart] received, process restarting
Mon Jun  8 15:03:11 2020 us=201169 Restart pause, 5 second(s)

Server log

Mon Jun  8 07:02:11 2020 us=535762 MULTI: multi_create_instance called
Mon Jun  8 07:02:11 2020 us=535887 101.118.29.231:36723 Re-using SSL/TLS context
Mon Jun  8 07:02:11 2020 us=535983 101.118.29.231:36723 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Mon Jun  8 07:02:11 2020 us=536005 101.118.29.231:36723 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Mon Jun  8 07:02:11 2020 us=536059 101.118.29.231:36723 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Mon Jun  8 07:02:11 2020 us=536072 101.118.29.231:36723 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Mon Jun  8 07:02:11 2020 us=536105 101.118.29.231:36723 TLS: Initial packet from [AF_INET]101.118.29.231:36723, sid=15946bcb f4a41b79
Mon Jun  8 07:02:21 2020 us=14167 101.118.29.231:40414 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mon Jun  8 07:02:21 2020 us=14200 101.118.29.231:40414 TLS Error: TLS handshake failed
Mon Jun  8 07:02:21 2020 us=14307 101.118.29.231:40414 SIGUSR1[soft,tls-error] received, client-instance restarting
Mon Jun  8 07:03:11 2020 us=19990 101.118.29.231:36723 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mon Jun  8 07:03:11 2020 us=20044 101.118.29.231:36723 TLS Error: TLS handshake failed
Mon Jun  8 07:03:11 2020 us=20161 101.118.29.231:36723 SIGUSR1[soft,tls-error] received, client-instance restarting
Mon Jun  8 07:03:16 2020 us=382468 MULTI: multi_create_instance called
Mon Jun  8 07:03:16 2020 us=382587 101.118.29.231:41486 Re-using SSL/TLS context
Mon Jun  8 07:03:16 2020 us=382674 101.118.29.231:41486 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Mon Jun  8 07:03:16 2020 us=382697 101.118.29.231:41486 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Mon Jun  8 07:03:16 2020 us=382751 101.118.29.231:41486 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Mon Jun  8 07:03:16 2020 us=382764 101.118.29.231:41486 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Mon Jun  8 07:03:16 2020 us=382796 101.118.29.231:41486 TLS: Initial packet from [AF_INET]101.118.29.231:41486, sid=069f7d46 6db7456b

I did update this today via apt
Upgrade: ca-certificates:amd64 (20161130+nmu1+deb9u1, 20200601~deb9u1)

Other than that 3 hours ago it worked... now it does not.
Could something have expired? (grasping at straws)

TinCanTech

stinga@wolf-rock.com wrote Could something have expired? (grasping at straws)

Possibly but it would not effect this part of the TLS handshake.

stinga@wolf-rock.com wrote Mon Jun 8 07:02:11 2020 us=536105 101.118.29.231:36723 TLS: Initial packet from [AF_INET]101.118.29.231:36723, sid=15946bcb f4a41b79
Mon Jun 8 07:02:21 2020 us=14167 101.118.29.231:40414 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Your server timed out the connection after 10 seconds, the default is 60 seconds ..

See --hand-window in the manual.

stinga@wolf-rock.com

Where would I find --hand-window?

I looked on the server and the client and can't find hand-window anywhere.

also the log states

Mon Jun  8 11:40:12 2020 us=9149 101.118.29.231:42921 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

Would that not mean that the default 60 seconds is being used?

Also the number after 101.118.29.231is different, port(?) I think I may have had two client connections going at that time.

A bit later..
I rebooted my isp router and now it works again. I noticed that I was not getting data from the server back to the client.
Whilst this resolves the linux issue I still have the same issue with the windows back.
And we have rebooted that isp router.

SO back to square one really, I am continuing to investigate!
Any thoughts gratefully received....

TinCanTech

stinga@wolf-rock.com wrote Would that not mean that the default 60 seconds is being used?

I checked and yes it does mean it's using 60 seconds.

stinga@wolf-rock.com wrote Also the number after 101.118.29.231is different, port(?) I think I may have had two client connections going at that time.

The ports are different, you were using two clients. I did not notice.

stinga@wolf-rock.com wrote Any thoughts gratefully received....

I don't understand the current situation, if one connects but another does not then check your server log at verb 4.

stinga@wolf-rock.com

Current situation is...
On the same home network:
1 - Linux box is connecting fine
2 - Windows box is not

Windows gets

Current situation is...
On the same home network:
1 - Linux box is connecting fine
2 - Windows box is not

Windows gets - from the server log
[code]Mon Jun  8 21:34:47 2020 us=640040 MULTI: multi_create_instance called
Mon Jun  8 21:34:47 2020 us=640181 94.9.29.181:57150 Re-using SSL/TLS context
Mon Jun  8 21:34:47 2020 us=640326 94.9.29.181:57150 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Mon Jun  8 21:34:47 2020 us=640378 94.9.29.181:57150 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Mon Jun  8 21:34:47 2020 us=640459 94.9.29.181:57150 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Mon Jun  8 21:34:47 2020 us=640491 94.9.29.181:57150 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Mon Jun  8 21:34:47 2020 us=640528 94.9.29.181:57150 TLS: Initial packet from [AF_INET]94.9.29.181:57150, sid=7eef6279 36ae888c
Mon Jun  8 21:35:48 2020 us=46275 94.9.29.181:57150 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mon Jun  8 21:35:48 2020 us=46332 94.9.29.181:57150 TLS Error: TLS handshake failed
Mon Jun  8 21:35:48 2020 us=46438 94.9.29.181:57150 SIGUSR1[soft,tls-error] received, client-instance restarting

Here is the linux box data from the server:

Mon Jun  8 22:24:58 2020 us=5305 obdave/94.9.29.181:44628 TLS: soft reset sec=0 bytes=141592496/-1 pkts=185977/0
Mon Jun  8 22:24:58 2020 us=214167 obdave/94.9.29.181:44628 VERIFY SCRIPT OK: depth=1, C=UK, ST=Cornwall, L=Penzance, O=coastfm, OU=Technical, CN=coastfm CA, emailAddress=mikephillips@coastfm.co.uk
Mon Jun  8 22:24:58 2020 us=214230 obdave/94.9.29.181:44628 VERIFY OK: depth=1, C=UK, ST=Cornwall, L=Penzance, O=coastfm, OU=Technical, CN=coastfm CA, emailAddress=mikephillips@coastfm.co.uk
Mon Jun  8 22:24:58 2020 us=290743 obdave/94.9.29.181:44628 VERIFY SCRIPT OK: depth=0, C=UK, ST=Cornwall, O=coastfm, CN=obdave
Mon Jun  8 22:24:58 2020 us=290812 obdave/94.9.29.181:44628 VERIFY OK: depth=0, C=UK, ST=Cornwall, O=coastfm, CN=obdave
Mon Jun  8 22:24:58 2020 us=291493 obdave/94.9.29.181:44628 peer info: IV_VER=2.4.7
Mon Jun  8 22:24:58 2020 us=291537 obdave/94.9.29.181:44628 peer info: IV_PLAT=linux
Mon Jun  8 22:24:58 2020 us=291560 obdave/94.9.29.181:44628 peer info: IV_PROTO=2
Mon Jun  8 22:24:58 2020 us=291580 obdave/94.9.29.181:44628 peer info: IV_LZ4=1
Mon Jun  8 22:24:58 2020 us=291600 obdave/94.9.29.181:44628 peer info: IV_LZ4v2=1
Mon Jun  8 22:24:58 2020 us=291619 obdave/94.9.29.181:44628 peer info: IV_LZO=1
Mon Jun  8 22:24:58 2020 us=291637 obdave/94.9.29.181:44628 peer info: IV_COMP_STUB=1
Mon Jun  8 22:24:58 2020 us=291659 obdave/94.9.29.181:44628 peer info: IV_COMP_STUBv2=1
Mon Jun  8 22:24:58 2020 us=291680 obdave/94.9.29.181:44628 peer info: IV_TCPNL=1
Mon Jun  8 22:24:58 2020 us=291948 obdave/94.9.29.181:44628 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Mon Jun  8 22:24:58 2020 us=291996 obdave/94.9.29.181:44628 Outgoing Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
Mon Jun  8 22:24:58 2020 us=292021 obdave/94.9.29.181:44628 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Mon Jun  8 22:24:58 2020 us=292049 obdave/94.9.29.181:44628 Incoming Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
Mon Jun  8 22:24:58 2020 us=319474 obdave/94.9.29.181:44628 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_CHACHA20_POLY1305_SHA256, 2048 bit RSA

TinCanTech

TinCanTech wrote check your server log at verb 4.

stinga@wolf-rock.com

I have posted the server log above, am I posting the wrong thing or not enough data? Here is the relevant bit (I think)

un 10 06:01:51 cf-fw openvpnserver[24975]: MULTI: multi_create_instance called
Jun 10 06:01:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 Re-using SSL/TLS context
Jun 10 06:01:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Jun 10 06:01:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Jun 10 06:01:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Jun 10 06:01:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Jun 10 06:01:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 TLS: Initial packet from [AF_INET]94.9.29.181:57445, sid=8dbbf1a8 f2d64bda
Jun 10 06:02:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Jun 10 06:02:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 TLS Error: TLS handshake failed
Jun 10 06:02:51 cf-fw openvpnserver[24975]: 94.9.29.181:57445 SIGUSR1[soft,tls-error] received, client-instance restarting

Presently I am investigating a useless router as being the issue. Also trying to get the user to use another internet location and see if it works, so we can eliminate the actual laptop as the issue. I have a feeling it is the router causing issues. We have rebooted it though, there is no firewall active on it and as noted previously, a linux box behind the router on the same network is working.

Thanks!

stinga@wolf-rock.com

Stupid poxy openreach, turns out it was the wall socket, why linux worked is beyond me, but the user had an engineer out and the wall socket was replaced, probably the filter.

Any way, all devices now get VPN access again.

TinCanTech

stinga@wolf-rock.com wrote turns out it was the wall socket

At least you have the culprit.

FYI: When both server and client have the same TLS error:

stinga@wolf-rock.com wrote TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

This almost always indicates some form of actual network problem. Usually firewall ..

stinga@wolf-rock.com wrote why linux worked is beyond me

With UDP, probably just lucky .. just enough packets getting through. TCP would almost certainly have failed all around.

stinga@wolf-rock.com wrote all devices now get VPN access again

Thanks for letting us know 8-)