TLS handshake failed intermittently



  • Hello,

    I am running pfSense 2.2.3 (nanobsd) with an OpenVPN server utilizing the following options:

    • Server Mode: Remote Access (SSL/TLS + User Auth)

    • Backend for authentication: AD + Local Database

    • Protocol: UDP

    • TLS Authentication: checked

    • DH Parameters Length: 4096

    • I am pushing "tun-mtu 1400;" to the clients

    OpenVPN clients are using the OpenVPN Windows installer (x86-win6) generated by the OpenVPN Client Export Utility pfSense package. They can usually authenticate just fine, however occasionally they will fail when attempting to connect with the following error in the OpenVPN server logs:

    openvpn[16537]: 1.2.3.4:5678 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400)
    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
    Oct 20 15:34:17	openvpn[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:17	openvpn[16537]: 1.2.3.4:5678 TLS Error: TLS object -> incoming plaintext read error
    Oct 20 15:34:17	openvpn[16537]: 1.2.3.4:5678 TLS Error: TLS handshake failed
    

    If the user keeps retrying, eventually the error will disappear and they will connect normally. What can I do to determine the reason for this TLS error and how to prevent it from happening?

    Thanks!


  • LAYER 8 Global Moderator

    There error points to a problem with you certs most likely.. What does the client log say?



  • 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



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


  • LAYER 8 Global Moderator

    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?



  • 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
    

  • LAYER 8 Global Moderator

    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.




  • 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?


  • LAYER 8 Global Moderator

    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.




  • 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


  • LAYER 8 Global Moderator

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



  • 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?


  • LAYER 8 Global Moderator

    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.



  • 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.


  • LAYER 8 Global Moderator

    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



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


  • LAYER 8 Global Moderator

    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


Log in to reply