Connections suddenly hang on TLS negotiation failure

cbraxton

This is an OpenVPN setup running on Windows Server 2016 on the server end. It recently stopped working though there have been no configuration changes since it was set up in 2018 (unless someone else changed it). The only known changes are Windows updates which should not affect OpenVPN. Version on the server end is 2.6.4-I601. This is a very basic "road warrior" setup and has worked now for a few years, until sometime in the last few weeks. I've done web searches but not yet found any suggestions that work. Any light someone on the forum here can shed on this problem would be greatly appreciated.

In order to replicate the problem for testing I set up a test VM using Windows 10 and OpenVPN 2.6.9 (same as one of the affected clients) using the same client configuration. The connection just sits and hangs, retries after 60 seconds, keeps retrying, and ultimately has to be aborted. The following is the connection log with personal info redacted:

Fri Aug 13 18:06:44 2021 OpenVPN 2.4.9 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Apr 16 2020
Fri Aug 13 18:06:44 2021 Windows version 6.2 (Windows 8 or greater) 64bit
Fri Aug 13 18:06:44 2021 library versions: OpenSSL 1.1.1f 31 Mar 2020, LZO 2.10
Fri Aug 13 18:06:44 2021 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25344
Fri Aug 13 18:06:44 2021 Need hold release from management interface, waiting...
Fri Aug 13 18:06:45 2021 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25344
Fri Aug 13 18:06:45 2021 MANAGEMENT: CMD 'state on'
Fri Aug 13 18:06:45 2021 MANAGEMENT: CMD 'log all on'
Fri Aug 13 18:06:45 2021 MANAGEMENT: CMD 'echo all on'
Fri Aug 13 18:06:45 2021 MANAGEMENT: CMD 'bytecount 5'
Fri Aug 13 18:06:45 2021 MANAGEMENT: CMD 'hold off'
Fri Aug 13 18:06:45 2021 MANAGEMENT: CMD 'hold release'
Fri Aug 13 18:06:45 2021 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Aug 13 18:06:45 2021 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Fri Aug 13 18:06:45 2021 MANAGEMENT: >STATE:1628892405,RESOLVE,,,,,,
Fri Aug 13 18:06:45 2021 TCP/UDP: Preserving recently used remote address: [AF_INET]IP_ADDRESS:1194
Fri Aug 13 18:06:45 2021 Socket Buffers: R=[65536->65536] S=[65536->65536]
Fri Aug 13 18:06:45 2021 UDPv4 link local: (not bound)
Fri Aug 13 18:06:45 2021 UDPv4 link remote: [AF_INET]IP_ADDRESS:1194
Fri Aug 13 18:06:45 2021 MANAGEMENT: >STATE:1628892405,WAIT,,,,,,
Fri Aug 13 18:06:45 2021 MANAGEMENT: >STATE:1628892405,AUTH,,,,,,
Fri Aug 13 18:06:45 2021 TLS: Initial packet from [AF_INET]IP_ADDRESS:1194, sid=ea2e3f95 73afb423
Fri Aug 13 18:06:45 2021 VERIFY OK: depth=1, C=US, ST=XX, L=XXXXX, O=xxxxx, OU=XXXXX, CN=XXXXX, name=XXXXX, emailAddress=XXXX@XXXXX.com
Fri Aug 13 18:06:45 2021 VERIFY KU OK
Fri Aug 13 18:06:45 2021 Validating certificate extended key usage
Fri Aug 13 18:06:45 2021 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Fri Aug 13 18:06:45 2021 VERIFY EKU OK
Fri Aug 13 18:06:45 2021 VERIFY OK: depth=0, C=US, ST=XX, L=XXXXX, O=XXXXX, OU=XXXXX, CN=XXXXX, name=server, emailAddress=XXXX@XXXXX.com
Fri Aug 13 18:07:45 2021 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Fri Aug 13 18:07:45 2021 TLS Error: TLS handshake failed
Fri Aug 13 18:07:45 2021 SIGUSR1[soft,tls-error] received, process restarting
Fri Aug 13 18:07:45 2021 MANAGEMENT: >STATE:1628892465,RECONNECTING,tls-error,,,,,
Fri Aug 13 18:07:45 2021 Restart pause, 5 second(s)
Fri Aug 13 18:07:50 2021 MANAGEMENT: >STATE:1628892470,RESOLVE,,,,,,
Fri Aug 13 18:07:50 2021 TCP/UDP: Preserving recently used remote address: [AF_INET]IP_ADDRESS:1194
Fri Aug 13 18:07:50 2021 Socket Buffers: R=[65536->65536] S=[65536->65536]
Fri Aug 13 18:07:50 2021 UDPv4 link local: (not bound)
Fri Aug 13 18:07:50 2021 UDPv4 link remote: [AF_INET]IP_ADDRESS:1194
Fri Aug 13 18:07:50 2021 MANAGEMENT: >STATE:1628892470,WAIT,,,,,,
Fri Aug 13 18:07:50 2021 MANAGEMENT: >STATE:1628892470,AUTH,,,,,,
Fri Aug 13 18:07:50 2021 TLS: Initial packet from [AF_INET]IP_ADDRESS:1194, sid=dfbd1fa0 078da748
Fri Aug 13 18:07:50 2021 VERIFY OK: depth=1, C=US, ST=XX, L=XXXXX, O=XXXXX, OU=XXXXX, CN=XXXXX, name=XXXXX, emailAddress=XXXX@XXXXX.com
Fri Aug 13 18:07:50 2021 VERIFY KU OK
Fri Aug 13 18:07:50 2021 Validating certificate extended key usage
Fri Aug 13 18:07:50 2021 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Fri Aug 13 18:07:50 2021 VERIFY EKU OK
Fri Aug 13 18:07:50 2021 VERIFY OK: depth=0, C=US, ST=XX, L=XXXXX, O=XXXXX, OU=XXXXX, CN=XXXXX, name=XXXXX, emailAddress=XXXX@XXXXX.com
Fri Aug 13 18:08:50 2021 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Fri Aug 13 18:08:50 2021 TLS Error: TLS handshake failed
Fri Aug 13 18:08:50 2021 SIGUSR1[soft,tls-error] received, process restarting
Fri Aug 13 18:08:50 2021 MANAGEMENT: >STATE:1628892530,RECONNECTING,tls-error,,,,,
Fri Aug 13 18:08:50 2021 Restart pause, 5 second(s)
[...retries several times, finally abort manually...]
Fri Aug 13 18:28:16 2021 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Fri Aug 13 18:28:16 2021 TLS Error: TLS handshake failed
Fri Aug 13 18:28:16 2021 SIGUSR1[soft,tls-error] received, process restarting
Fri Aug 13 18:28:16 2021 MANAGEMENT: >STATE:1628893696,RECONNECTING,tls-error,,,,,
Fri Aug 13 18:28:16 2021 Restart pause, 300 second(s)
Fri Aug 13 18:30:37 2021 SIGTERM[hard,init_instance] received, process exiting
Fri Aug 13 18:30:37 2021 MANAGEMENT: >STATE:1628893837,EXITING,init_instance,,,,,

Here is the server configuration:

port 1194
proto udp4
dev tun
dev-node OpenVPN_TAP
ca C:\\PROGRA~1\\OpenVPN\\easy-rsa\\keys\\ca.crt
cert C:\\PROGRA~1\\OpenVPN\\easy-rsa\\keys\\server.crt
key C:\\PROGRA~1\\OpenVPN\\easy-rsa\\keys\\server.key
dh C:\\PROGRA~1\\OpenVPN\\easy-rsa\\keys\\dh2048.pem
tls-auth C:\\PROGRA~1\\OpenVPN\\easy-rsa\\keys\\ta.key 0
tap-sleep 3
route-delay 1 3
server 10.8.0.0 255.255.255.0
ip-win32 netsh
ifconfig-pool-persist ipp.txt
push "route 192.168.0.0 255.255.255.0"
keepalive 10 120
comp-lzo
cipher AES-256-CBC
status openvpn-status.log
verb 3
mute 20
crl-verify C:\\PROGRA~1\\OpenVPN\\easy-rsa\\keys\\crl.pem
management localhost 7505

Here is the client configuration:

client
dev tun
proto udp4
remote IP_ADDRESS 1194
resolv-retry infinite
nobind
persist-key
persist-tun
ca c:\\progra~1\\openvpn\\easy-rsa\\keys\\ca.crt
cert c:\\progra~1\\openvpn\\easy-rsa\\keys\\USER.crt
key c:\\progra~1\\openvpn\\easy-rsa\\keys\\USER.key
remote-cert-tls server
tls-auth c:\\progra~1\\openvpn\\easy-rsa\\keys\\fands\\ta.key 1
cipher AES-256-CBC
comp-lzo
verb 3
auth-nocache

TinCanTech

Only somebody who would run an OpenVPN Server on Wind-blows would also omit their server log.

cbraxton

TinCanTech wrote Only somebody who would run an OpenVPN Server on Wind-blows would also omit their server log.

Why thank you for that useful and informative answer. As it happens, this location originally had a Linux server with OpenVPN but an application requirement for Win-blows on the back end required a move to that operating system. OpenVPN, which had been functioning well for years, was brought over including the previous configuration, just modified as needed for Win-blows.

However, you are correct that the server log should have been checked and included. (Sometimes it takes a kick in the head to know you've overlooked the obvious - easy to do when fighting multiple fires.) Looking over the log it looks like the problem is the CRL has expired due to OpenVPN version 2.4 checking for an expired nextUpdate field in the CRL where previous versions did not.

Fri Aug 13 20:53:44 2021 us=69868 45.133.182.252:40040 VERIFY ERROR: depth=0, error=CRL has expired: C=US, ST=XX, L=XXXXX O=XXXXX , OU=XXXXX, CN=XXXXX, name=XXXXX, emailAddress=XXXX@XXXXX.com
Fri Aug 13 20:53:44 2021 us=69868 45.133.182.252:40040 OpenSSL: error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed
Fri Aug 13 20:53:44 2021 us=69868 45.133.182.252:40040 TLS_ERROR: BIO read tls_read_plaintext error
Fri Aug 13 20:53:44 2021 us=69868 45.133.182.252:40040 TLS Error: TLS object -> incoming plaintext read error
Fri Aug 13 20:53:44 2021 us=69868 45.133.182.252:40040 TLS Error: TLS handshake failed

The fix is to generate a new CRL using easyrsa3 but easyrsa2 was used to generate everything here. Actually I had been thinking along the lines of moving to easyrsa3 and updating everything to the latest version anyway. To this end I downloaded easyrsa 3.0.8 from github. Unfortunately it doesn't seem to work too well on Win-blows. (Yes, I read the Win-blows README.) After suitably editing vars for site info this is the result (only error output shown)...

cd EasyRSA-3.0.8
cp openssl-easyrsa.cnf pki # This cnf file needs to be in pki
.\EasyRSA-Start.bat
./easyrsa pki-init
./easyrsa build-ca nopass
./easyrsa build-server-full server nopass

Easy-RSA error:

Unknown cert type 'server'

Easy-RSA error:

Failed to sign 'server'

Not sure why this is happening. From what I can find it looks like easyrsa cannot find the X509-types subdirectory, but it is where it is supposed to be. I tried putting the complete path into vars (filespec format as in the README) but that didn't help. So that's where it sits and probably I should start a new thread for this since now this is a completely different problem.

TinCanTech

As you can see, without your server log we could not help you and with it you helped yourself ..

Easy-RSAv3 can be installed correctly when you install Openvpn, use "Custom" settings to install it.

cbraxton

Yes, it my own mistake/omission just looking at the client log file. The server log made it very clear what was happening.

As far as EasyRSA goes,I thought I'd try the latest standalone release from github but it obviously has some issues running on Redmond's finest. (Might have to do with spaces in the path according to some info I've found.) However, when I update to the latest OpenVPN release I'll try installing it via the custom settings as suggested.

cbraxton

Well I installed the latest OpenVPN, including easy-rsa, and it still doesn't work, same error. I tried moving the easy-rsa subdirectory to c:\easy-rsa due to reports that spaces in the path can be a problem, but it still does not work. In addition the following warning is being reported:

WARNING: can't open config file: C:/Program Files/OpenVPN/easy-rsa/pki/safessl-easyrsa.cnf

TinCanTech

https://github.com/OpenVPN/easy-rsa/issues/412

Instead of the root directory, try using your user's home directory.

cbraxton

OK, moved C:\easy-rsa to C:\Users\Administrator\easy-rsa. Ran pki-init to start out fresh. Same result, build-server-full fails, doesn't recognize the cert-type server despite the presence of x509-types directly under the easy-rsa directory. I also tried editing the vars file and adding set_var EASYRSA_EXT_DIR "C:/Users/Administrator/easy-rsa/x509-types". Same result, signing fails.

Also the warning about not finding safessl-easyrsa.cnf persists, but that appears not to be a fatal error.

I checked permissions and nothing jumps out at me aside from the fact that I hate working with Win-blows (administrator has full access to everything in the easy-rsa directory heirarchy). Error messages below.

EasyRSA Shell
# ./easyrsa build-server-full server nopass
WARNING: can't open config file: C:/Users/Administrator/easy-rsa/pki/safessl-easyrsa.cnf
WARNING: can't open config file: C:/Users/Administrator/easy-rsa/pki/safessl-easyrsa.cnf
Using SSL: openssl OpenSSL 1.0.2n 7 Dec 2017
path = C:/Users/Administrator/easy-rsa/pki/easy-rsa-10196.a13560/tmp.XXXXXX
lpPathBuffer = C:\Users\ADMINI~1\AppData\Local\Temp\1\
szTempName = C:\Users\ADMINI~1\AppData\Local\Temp\1\tmp517F.tmp
path = C:\Users\ADMINI~1\AppData\Local\Temp\1\tmp517F.tmp
fd = 3
path = C:/Users/Administrator/easy-rsa/pki/easy-rsa-10196.a13560/tmp.XXXXXX
lpPathBuffer = C:\Users\ADMINI~1\AppData\Local\Temp\1\
szTempName = C:\Users\ADMINI~1\AppData\Local\Temp\1\tmp521B.tmp
path = C:\Users\ADMINI~1\AppData\Local\Temp\1\tmp521B.tmp
fd = 3
path = C:/Users/Administrator/easy-rsa/pki/easy-rsa-10196.a13560/tmp.XXXXXX
lpPathBuffer = C:\Users\ADMINI~1\AppData\Local\Temp\1\
szTempName = C:\Users\ADMINI~1\AppData\Local\Temp\1\tmp52E6.tmp
path = C:\Users\ADMINI~1\AppData\Local\Temp\1\tmp52E6.tmp
fd = 3
WARNING: can't open config file: C:/Users/Administrator/easy-rsa/pki/safessl-easyrsa.cnf
Generating a 2048 bit RSA private key
...+++
...............................+++
writing new private key to 'C:/Users/Administrator/easy-rsa/pki/easy-rsa-10196.a13560/tmp.a16404'
-----
WARNING: can't open config file: C:/Users/Administrator/easy-rsa/pki/safessl-easyrsa.cnf
Generating a 2048 bit RSA private key
...+++
...............................+++
writing new private key to 'C:/Users/Administrator/easy-rsa/pki/easy-rsa-10196.a13560/tmp.a16404'
-----
WARNING: can't open config file: C:/Users/Administrator/easy-rsa/pki/safessl-easyrsa.cnf

Easy-RSA error:

Unknown cert type 'server'

Easy-RSA error:

Failed to sign 'server'

EasyRSA Shell
#
[/opass]

cbraxton

Now this is bizarre...

I maintain a Windows server at another site also running OpenVPN. (Once again this replaced an old Linux server due to application requirements.) That one is running Windows Server 2019 operating system with OpenVPN 2.5.0 and it has a functioning easyrsa3 installation.

For test purposes I copied the entire easyrsa directory tree from there to the problem machine which runs Windows Server 2016. This was placed in the same location, root of the system drive. Attempting the command "./easyrsa build-client-full testing nopass" fails with the diagnostic "unknown cert type client". Going back to the Server 2019 machine, running the same command works with no problem.

So what difference between these two Win-blows servers would cause the exact same easyrsa3 setup to work on one and fail on the other?

Another data point - just to make things more interesting as another test I downloaded a fresh copy of easyrsa 3.0.8 to a Windows 10 workstation I have access to located at the same site as the problem server. I made the same site customizations to the vars file, then ran init-pki, build-ca, build-server-full, and build-client full. No errors, no warnings, it just worked. (So I guess there's no voodoo going on in that building that's causing the problem.)

cbraxton

Anyhow, I got the latest OpenVPN working by using that Windows 10 workstation to build the live pki, then moved it over to the server. Of course for now any changes such as adding or revoking clients will need to be done on another machine and moved over to the server so it's not really a fix but a workaround. The underlying problem with easyrsa3 running on that Windows Server 2016 system is still there.

TinCanTech

Now that you have Easy-RSA working, you could also try:
https://github.com/TinCanTech/easy-tls

Feed-back welcome.

cbraxton

I saw easy-tls and will have to take a look at it. I'm still adjusting to easyrsa3 at this point though after having used easyrsa2 for many years.