TLS handshake failed intermittently

amartin

The client log says:


TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
TLS Error: TLS handshake failed

I do not believe this to be a network connectivity issue since I have reproduced this problem on a variety of different networks. After retrying for a period of time without changing anything, this will start to connect successfully

amartin

Ticket #4329 seems very similar. In my case, the certificate depth is set to "One (Client + Server)"

johnpoz

Not sure where they thought the default is none in that bug report, the default is one (client+server) and I have not seen any issues like this. Are you using intermediate CAs from your certs?

That network connectivity error is generic since the negotiation failed to occur in a time out.. But if you have issues with certs and the handshake doesn't happen then sure there would be a time out in the negotiation, etc..

Are you users all using the same certs, do they all have their own?

amartin

I'm not using any intermediate CAs - I just created a new CA through the pfSense web interface and am it to issue the certificates. Each user has their own certificate, but even if a certificate was being shared I have the "Strict User/CN Matching" box on the OpenVPN server config page unchecked, so I think they shouldn't conflict.

This error on the server side seems to indicate that OpenVPN is calling some external program for the verification and said program is exiting with a non-zero exit code:

Oct 20 15:34:17	openvpn[16537]: 1.2.3.4:5678 WARNING: Failed running command (--tls-verify script): external program exited with error status: 1

johnpoz

Can you post your certs and ca your using.. Have seen multiple issues lately with users of the CA manager not doing the correct certs.. For your openvpn IMHO it is best to create a CA for that specific use, then you need a server cert and then users need to be user certs..

I think that error could also be generic if certs not handled properly, etc..

From the errors before

Oct 20 15:34:17openvpn[16537]: 1.2.3.4:5678 TLS_ERROR: BIO read tls_read_plaintext error: error:140890B2:SSL routines:SSL3_GET_CLIENT_CERTIFICATE:no certificate returned
Oct 20 15:34:17openvpn[16537]: 1.2.3.4:5678 TLS Error: TLS object -> incoming plaintext read error
Oct 20 15:34:17openvpn[16537]: 1.2.3.4:5678 TLS Error: TLS handshake failed

Where you don't get a cert or "no certificate returned" Then it would make sense that a verify function would fail.

If you export your ca.crt and your server.crt and user.crt you should be able to verify them against your ca as a sanity check

example
root@clean:/home/user# openssl verify -CAfile openvpn.crt johnpoz.crt
johnpoz.crt: OK
root@clean:/home/user# openssl verify -CAfile openvpn.crt pfsenseopenvpn.crt
pfsenseopenvpn.crt: OK
root@clean:/home/user#

You can export them from the ca manager.

caandcerts.png_thumb

amartin

I double-checked my certificates and OpenVPN config and they match the screenshots you posted exactly (aside from the names). I have a CA dedicated for OpenVPN, a server certificate (which OpenVPN is configured to use) from said CA and each user certificate is marked as a user certificate from that same CA. So this part of it looks correct - is there anything else I should check?

johnpoz

Can you verify you certs with my above edited example.. Do you have spaces in your CN, etc..? Can you output the certs info, see attached as example.. Make sure if you obfuscate you don't hide spaces in names, etc. etc.

certinfo.png_thumb

amartin

I ran the verify commands as per your example and both the OpenVPN server and the client certificates returned "OK". Here's the output with the certs info (any obfuscation done preserves whitespace and formatting):
http://pastebin.com/6tykJxnh

johnpoz

For grins I would remove those spaces "My Example Company LLC" Can't hurt not to have spaces, use _ of you want, etc..

amartin

That's a good idea, however you can't edit an existing CA or certificate, correct? Therefore I would have to regenerate all of my certificates, which isn't feasible unless I know this is a definite solution. It seems unlikely that there is something wrong with the certificate since it does connect successfully some of the time - if the certificate were malformed/invalid in some way, wouldn't it fail 100% of the time?

johnpoz

Well when they connect correctly what does the log say did it run the verify script what was its output. Can you not just bring up another instance of openvpn with new ca and no spaces used in the ca and certs, etc. And then test with that instance and the new certs? If that fails to have problems then you can schedule to make the full blown switch, etc.

amartin

A successful connection looks like this:

Oct 21 21:22:53 openvpn[16537]: 1.2.3.4:56789 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400)
Oct 21 21:22:57 openvpn: user 'user1' authenticated
Oct 21 21:22:57 openvpn[16537]: 1.2.3.4:56789 [user1] Peer Connection Initiated with [AF_INET]1.2.3.4:56789
Oct 21 21:22:59 openvpn[16537]: user1/1.2.3.4:56789 send_push_reply(): safe_cap=940

I did some digging and it looks like the –tls-verify argument calls this external script:

/etc/inc/openvpn.inc:                           $conf .= "tls-verify \"/usr/local/sbin/ovpn_auth_verify tls '{$servercn}' {$settings['cert_depth']} \"\n";

I'm adding some additional debug code to /usr/local/sbin/ovpn_auth_verify to see if I can determine why it is failing.

johnpoz

why in successful connection are you not seeing the output of verify.. For example..

Thu Oct 22 09:25:25 2015 TLS: Initial packet from [AF_INET]10.56.226.130:8080, sid=4a03d18e b95c8636
Thu Oct 22 09:25:26 2015 VERIFY OK: depth=1, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpoz@snipped, CN=openvpn
Thu Oct 22 09:25:26 2015 VERIFY OK: nsCertType=SERVER
Thu Oct 22 09:25:26 2015 VERIFY X509NAME OK: C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpoz@snipped, CN=pfsenseopenvpn
Thu Oct 22 09:25:26 2015 VERIFY OK: depth=0, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpoz@snipped, CN=pfsenseopenvpn
Thu Oct 22 09:25:28 2015 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key

That is connection just did this morning to my home vpn, bouncing off a proxy here at work is why you see the 10.x address..

Here is the server side of that connection

ct 22 09:25:28 openvpn[18640]: publicIP:63794 [johnpoz] Peer Connection Initiated with [AF_INET]snipped:63794
Oct 22 09:25:28 openvpn[18640]: publicIP:63794 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 VERIFY OK: depth=0, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpoz@snipped, CN=johnpoz
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 VERIFY SCRIPT OK: depth=0, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpoz@snipped, CN=johnpoz
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 VERIFY OK: depth=1, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpoz@snipped, CN=openvpn
Oct 22 09:25:27 openvpn[18640]: publicIP:63794 VERIFY SCRIPT OK: depth=1, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpoz@snipped, CN=openvpn
Oct 22 09:25:24 openvpn[18640]: publicIP:63794 TLS: Initial packet from [AF_INET]snipped:63794, sid=8c04eca5 218781cf

amartin

Hm… I have the "Verbosity level" in the OpenVPN server config set to 3 - maybe it needs to be higher to show those messages?

johnpoz

my client is set to 3 as well, server is set to 4.. let me set it down to 3 and reconnect.

Ok just reconnected server set to 3 and still see it verify.

Oct 22 14:28:22 openvpn[12190]: publicIP:63992 [johnpoz] Peer Connection Initiated with [AF_INET]publicIP:63992
Oct 22 14:28:22 openvpn[12190]: publicIP:63992 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Oct 22 14:28:22 openvpn[12190]: publicIP:63992 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Oct 22 14:28:22 openvpn[12190]: publicIP:63992 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Oct 22 14:28:22 openvpn[12190]: publicIP:63992 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Oct 22 14:28:22 openvpn[12190]: publicIP:63992 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Oct 22 14:28:21 openvpn[12190]: publicIP:63992 VERIFY OK: depth=0, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpozsnipped, CN=johnpoz
Oct 22 14:28:21 openvpn[12190]: publicIP:63992 VERIFY SCRIPT OK: depth=0, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpozsnipped, CN=johnpoz
Oct 22 14:28:21 openvpn[12190]: publicIP:63992 VERIFY OK: depth=1, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpozsnipped, CN=openvpn
Oct 22 14:28:21 openvpn[12190]: publicIP:63992 VERIFY SCRIPT OK: depth=1, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpozsnipped, CN=openvpn
Oct 22 14:28:17 openvpn[12190]: publicIP:63992 TLS: Initial packet from [AF_INET]publicIP:63992, sid=6f5a2a44 6d92e177
Oct 22 14:28:17 openvpn[12190]: TCP connection established with [AF_INET]publicIP:63992

client

Thu Oct 22 14:28:17 2015 TLS: Initial packet from [AF_INET]10.56.226.130:8080, sid=ba339956 9c9fc85c
Thu Oct 22 14:28:19 2015 VERIFY OK: depth=1, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpozsnipped, CN=openvpn
Thu Oct 22 14:28:19 2015 VERIFY OK: nsCertType=SERVER
Thu Oct 22 14:28:19 2015 VERIFY X509NAME OK: C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpozsnipped, CN=pfsenseopenvpn
Thu Oct 22 14:28:19 2015 VERIFY OK: depth=0, C=US, ST=IL, L=Schaumburg, O=Home, emailAddress=johnpozsnipped, CN=pfsenseopenvpn
Thu Oct 22 14:28:22 2015 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Thu Oct 22 14:28:22 2015 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Oct 22 14:28:22 2015 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Thu Oct 22 14:28:22 2015 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Oct 22 14:28:22 2015 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Thu Oct 22 14:28:22 2015 [pfsenseopenvpn] Peer Connection Initiated with [AF_INET]10.56.226.130:8080