TLS handshake failed intermittently

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