OpenVPN will hang with connected status in case of cipher mismatch

[hunterx1]

When attempting to connect to my PIA VPN provider with GCM as the ovpn configured cipher, OpenVPN will show connected status, but will actually be hung without a connection at all. Going into sleep mode will NOT result in a reconnect attempt. The log will be frozen at the initial connection attempt. The connection slider was in the ON position, and the VPN status bar indicator was present.

PIA has confirmed that AES-128-GCM, and AES-256-GCM (or any GCM) is not supported at this time. All the supported CBC ciphers work as expected with OpenVPN.

I have tested the same GCM ovpn file with another OpenVPN client, and that resulted with a failed handshake. The client correctly failed and terminated the connection.

logs look normal, and no crash reports exist.

[Antonio Quartulli]

Could you please share the log of the non-working attempt using OpenVPN Connect?

Which other client works as"expected" by failing the handshake? Are you talking about Connect for Android?

[hunterx1]

2018-03-07 23:27:18 ----- OpenVPN Start -----
OpenVPN core 3.2 ios arm64 64-bit built on Feb 22 2018 12:39:28
2018-03-07 23:27:18 Frame=512/2048/512 mssfix-ctrl=1250
2018-03-07 23:27:18 UNUSED OPTIONS
4 [resolv-retry] [infinite]
5 [nobind]
6 [persist-key]
7 [persist-tun]
11 [tls-client]
15 [verb] [1]

2018-03-07 23:27:18 EVENT: RESOLVE
2018-03-07 23:27:18 Contacting ???.???.???.???:1197/UDP via UDP
2018-03-07 23:27:18 EVENT: WAIT
2018-03-07 23:27:18 Connecting to [us-somewhere.privateinternetaccess.com]:1197 (xxx.xxx.xxx.xxx) via UDPv4
2018-03-07 23:27:18 EVENT: CONNECTING
2018-03-07 23:27:18 Tunnel Options:V4,dev-type tun,link-mtu 1522,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-GCM,auth SHA256,keysize 256,key-method 2,tls-client
2018-03-07 23:27:18 Creds: Username/Password?
2018-03-07 23:27:18 Peer Info:
IV_GUI_VER=net.openvpn.connect.ios 1.2.9-0
IV_VER=3.2
IV_PLAT=ios
IV_NCP=2
IV_TCPNL=1
IV_PROTO=2
IV_LZO=1
IV_IPv6=0

2018-03-07 23:27:18 VERIFY OK : depth=1
cert. version : 3
serial number : 9D:2E:FA:F3:83:64:99:ED
issuer name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=Private Internet Access, ??=Private Internet Access, emailAddress=secure@…
subject name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=Private Internet Access, ??=Private Internet Access, emailAddress=secure@…
issued on : 2014-04-17 17:40:33
expires on : 2034-04-12 17:40:33
signed using : RSA with SHA-512
RSA key size : 4096 bits
basic constraints : CA=true

2018-03-07 23:27:18 VERIFY OK : depth=0
cert. version : 3
serial number : DE:C2:A8:36:2F:97:60:78:76:44:03:62:E5:15:90:0A
issuer name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=Private Internet Access, ??=Private Internet Access, emailAddress=secure@…
subject name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=dec2a8362f97607876440362e515900a, ??=dec2a8362f97607876440362e515900a
issued on : 2016-07-04 19:35:17
expires on : 2036-06-29 19:35:17
signed using : RSA with SHA-512
RSA key size : 4096 bits
basic constraints : CA=false
cert. type : SSL Server
key usage : Digital Signature, Key Encipherment
ext key usage : TLS Web Server Authentication

2018-03-07 23:27:19 SSL Handshake: TLSv1.2/TLS-DHE-RSA-WITH-AES-256-GCM-SHA384
2018-03-07 23:27:19 Session is ACTIVE
2018-03-07 23:27:19 EVENT: GET_CONFIG
2018-03-07 23:27:19 Sending PUSH_REQUEST to server...
2018-03-07 23:27:20 Sending PUSH_REQUEST to server...
2018-03-07 23:27:20 OPTIONS:
0 [redirect-gateway] [def1]
1 [dhcp-option] [DNS] [xxx.xxx.xxx.xxx]
2 [dhcp-option] [DNS] [xxx.xxx.xxx.xxx]
3 [ping] [10]
4 [comp-lzo] [no]
5 [route] [10.83.10.1]
6 [topology] [net30]
7 [ifconfig] [10.83.10.6] [10.83.10.5]
8 [block-ipv6]

2018-03-07 23:27:20 PROTOCOL OPTIONS:

cipher: AES-256-GCM
digest: SHA256
compress: LZO_STUB
peer ID: -1

2018-03-07 23:27:20 EVENT: ASSIGN_IP
2018-03-07 23:27:20 NIP: preparing TUN network settings
2018-03-07 23:27:20 NIP: init TUN network settings with endpoint: 104.200.154.92
2018-03-07 23:27:20 NIP: adding IPv4 address to network settings 10.83.10.6/255.255.255.252
2018-03-07 23:27:20 NIP: adding (included) IPv4 route 10.83.10.4/30
2018-03-07 23:27:20 NIP: adding (included) IPv4 route 10.83.10.1/32
2018-03-07 23:27:20 NIP: redirecting all IPv4 traffic to TUN interface
2018-03-07 23:27:20 NIP: adding DNS xxx.xxx.xxx.xxx
2018-03-07 23:27:20 NIP: adding DNS xxx.xxx.xxx.xxx
2018-03-07 23:27:20 NIP: blocking all IPv6 traffic - not supported
2018-03-07 23:27:20 Connected via NetworkExtensionTUN
2018-03-07 23:27:20 LZO-ASYM init swap=0 asym=1
2018-03-07 23:27:20 Comp-stub init swap=0
2018-03-07 23:27:20 EVENT: CONNECTED me@…:1197 (104.200.154.92) via /UDPv4 on NetworkExtensionTUN/10.83.10.6/ gw=/
2018-03-07 23:28:01 Session invalidated: KEEPALIVE_TIMEOUT
2018-03-07 23:28:01 Client terminated, restarting in 2000 ms...
2018-03-07 23:28:03 EVENT: RECONNECTING
2018-03-07 23:28:03 Contacting [104.200.154.92]:1197/UDP via UDP
2018-03-07 23:28:03 EVENT: WAIT
2018-03-07 23:28:03 Connecting to [somewhere.privateinternetaccess.com]:1197 (ipaddress) via UDPv4
2018-03-07 23:28:03 EVENT: CONNECTING
2018-03-07 23:28:03 Tunnel Options:V4,dev-type tun,link-mtu 1522,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-GCM,auth SHA256,keysize 256,key-method 2,tls-client
2018-03-07 23:28:03 Creds: Username/Password?
2018-03-07 23:28:03 Peer Info:
IV_GUI_VER=net.openvpn.connect.ios 1.2.9-0
IV_VER=3.2
IV_PLAT=ios
IV_NCP=2
IV_TCPNL=1
IV_PROTO=2
IV_LZO=1
IV_IPv6=0

2018-03-07 23:28:04 VERIFY OK : depth=1
cert. version : 3
serial number : 9D:2E:FA:F3:83:64:99:ED
issuer name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=Private Internet Access, ??=Private Internet Access, emailAddress=secure@…
subject name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=Private Internet Access, ??=Private Internet Access, emailAddress=secure@…
issued on : 2014-04-17 17:40:33
expires on : 2034-04-12 17:40:33
signed using : RSA with SHA-512
RSA key size : 4096 bits
basic constraints : CA=true

2018-03-07 23:28:04 VERIFY OK : depth=0
cert. version : 3
serial number : DE:C2:A8:36:2F:97:60:78:76:44:03:62:E5:15:90:0A
issuer name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=Private Internet Access, ??=Private Internet Access, emailAddress=secure@…
subject name : C=US, ST=CA, L=LosAngeles?, O=Private Internet Access, OU=Private Internet Access, CN=dec2a8362f97607876440362e515900a, ??=dec2a8362f97607876440362e515900a
issued on : 2016-07-04 19:35:17
expires on : 2036-06-29 19:35:17
signed using : RSA with SHA-512
RSA key size : 4096 bits
basic constraints : CA=false
cert. type : SSL Server
key usage : Digital Signature, Key Encipherment
ext key usage : TLS Web Server Authentication

2018-03-07 23:28:05 SSL Handshake: TLSv1.2/TLS-DHE-RSA-WITH-AES-256-GCM-SHA384
2018-03-07 23:28:05 Session is ACTIVE
2018-03-07 23:28:05 EVENT: GET_CONFIG
2018-03-07 23:28:05 Sending PUSH_REQUEST to server...
2018-03-07 23:28:05 OPTIONS:
0 [redirect-gateway] [def1]
1 [dhcp-option] [DNS] [xxx.xxx.xxx.xxx]
2 [dhcp-option] [DNS] [xxx.xxx.xxx.xxx]
3 [ping] [10]
4 [comp-lzo] [no]
5 [route] [10.23.10.1]
6 [topology] [net30]
7 [ifconfig] [10.23.10.6] [10.23.10.5]
8 [block-ipv6]

2018-03-07 23:28:05 PROTOCOL OPTIONS:

cipher: AES-256-GCM
digest: SHA256
compress: LZO_STUB
peer ID: -1

2018-03-07 23:28:05 EVENT: ASSIGN_IP
2018-03-07 23:28:05 NIP: preparing TUN network settings
2018-03-07 23:28:05 NIP: init TUN network settings with endpoint: xxx.xxx.xxx.xxx
2018-03-07 23:28:05 NIP: adding IPv4 address to network settings 10.23.10.6/255.255.255.252
2018-03-07 23:28:05 NIP: adding (included) IPv4 route 10.23.10.4/30
2018-03-07 23:28:05 NIP: adding (included) IPv4 route 10.23.10.1/32
2018-03-07 23:28:05 NIP: redirecting all IPv4 traffic to TUN interface
2018-03-07 23:28:05 NIP: adding DNS ???
2018-03-07 23:28:05 NIP: adding DNS ???
2018-03-07 23:28:05 NIP: blocking all IPv6 traffic - not supported
2018-03-07 23:28:05 Connected via NetworkExtensionTUN
2018-03-07 23:28:05 LZO-ASYM init swap=0 asym=1
2018-03-07 23:28:05 Comp-stub init swap=0
2018-03-07 23:28:05 EVENT: CONNECTED me@…:1197 (???) via /UDPv4 on NetworkExtensionTUN/10.23.10.6/ gw=/

Sent from my iPhone

[hunterx1]

I think I saw it attempt to reconnect, so it may not be completely hung this time, no connection after connect.

[hunterx1]

Replying to ordex:

Which other client works as"expected" by failing the handshake? Are you talking about Connect for Android?

I used the openvpn client in my router because i wanted to test it at the same time? It's asuswrt merlin 384.3 on a RT-AC3200. They ripped out the closed source OpenVPN client, and replaced it with what I believe is something pure with more options. I installed pfsence in a VM with PIA as kinda a proof of concept for a separate project, and I believe that failed to connect as well, though I would need to try it again. I may install the latest version of OpenVPN for windows soon.

[hunterx1]

this is from my windows 10 PC with OpenVPN 2.4.5. It has a very similar issue.

Thu Mar 08 22:54:34 2018 OpenVPN 2.4.5 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Mar 1 2018
Thu Mar 08 22:54:34 2018 Windows version 6.2 (Windows 8 or greater) 64bit
Thu Mar 08 22:54:34 2018 library versions: OpenSSL 1.1.0f 25 May 2017, LZO 2.10
Enter Management Password:
Thu Mar 08 22:54:37 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]???:?
Thu Mar 08 22:54:37 2018 UDP link local: (not bound)
Thu Mar 08 22:54:37 2018 UDP link remote: [AF_INET]???:?
Thu Mar 08 22:54:37 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Thu Mar 08 22:54:37 2018 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1542'
Thu Mar 08 22:54:37 2018 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher BF-CBC'
Thu Mar 08 22:54:37 2018 WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1'
Thu Mar 08 22:54:37 2018 WARNING: 'keysize' is used inconsistently, local='keysize 256', remote='keysize 128'
Thu Mar 08 22:54:37 2018 [dec2a8362f97607876440362e515900a] Peer Connection Initiated with [AF_INET]????
Thu Mar 08 22:54:38 2018 open_tun
Thu Mar 08 22:54:38 2018 All TAP-Windows adapters on this system are currently in use.
Thu Mar 08 22:54:38 2018 Exiting due to fatal error
Thu Mar 08 22:56:42 2018 OpenVPN 2.4.5 x86_64-w64-mingw32 [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [AEAD] built on Mar 1 2018
Thu Mar 08 22:56:42 2018 Windows version 6.2 (Windows 8 or greater) 64bit
Thu Mar 08 22:56:42 2018 library versions: OpenSSL 1.1.0f 25 May 2017, LZO 2.10
Enter Management Password:
Thu Mar 08 22:56:44 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]????
Thu Mar 08 22:56:44 2018 UDP link local: (not bound)
Thu Mar 08 22:56:44 2018 UDP link remote: [AF_INET]????
Thu Mar 08 22:56:44 2018 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Thu Mar 08 22:56:45 2018 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1542'
Thu Mar 08 22:56:45 2018 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher BF-CBC'
Thu Mar 08 22:56:45 2018 WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1'
Thu Mar 08 22:56:45 2018 WARNING: 'keysize' is used inconsistently, local='keysize 256', remote='keysize 128'
Thu Mar 08 22:56:45 2018 [b22e22508fdbc9d0ce823eb0cef7a066] Peer Connection Initiated with [AF_INET]????
Thu Mar 08 22:56:51 2018 open_tun
Thu Mar 08 22:56:51 2018 TAP-WIN32 device [Ethernet 2] opened:
.\Global\{FCF44840-18FC-4778-8000-662390D6134C}.tap
Thu Mar 08 22:56:51 2018 Notified TAP-Windows driver to set a DHCP IP/netmask of 10.97.10.6/255.255.255.252 on interface {FCF44840-18FC-4778-8000-662390D6134C} [DHCP-serv: 10.97.10.5, lease-time: 31536000]
Thu Mar 08 22:56:51 2018 Successful ARP Flush on interface [13] {FCF44840-18FC-4778-8000-662390D6134C}
Thu Mar 08 22:56:51 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Thu Mar 08 22:56:56 2018 Initialization Sequence Completed
Thu Mar 08 22:57:01 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:57:11 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:57:21 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:57:30 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:57:41 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:57:51 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:58:01 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:58:12 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:58:22 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:58:32 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:58:42 2018 AEAD Decrypt error: cipher final failed
Thu Mar 08 22:58:51 2018 [b22e22508fdbc9d0ce823eb0cef7a066] Inactivity timeout (--ping-restart), restarting
Thu Mar 08 22:58:51 2018 SIGUSR1[soft,ping-restart] received, process restarting
Thu Mar 08 22:58:56 2018 TCP/UDP: Preserving recently used remote address: [AF_INET]????
Thu Mar 08 22:58:56 2018 UDP link local: (not bound)
Thu Mar 08 22:58:56 2018 UDP link remote: [AF_INET]????
Thu Mar 08 22:58:57 2018 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1542'
Thu Mar 08 22:58:57 2018 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher BF-CBC'
Thu Mar 08 22:58:57 2018 WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1'
Thu Mar 08 22:58:57 2018 WARNING: 'keysize' is used inconsistently, local='keysize 256', remote='keysize 128'
Thu Mar 08 22:58:57 2018 [b22e22508fdbc9d0ce823eb0cef7a066] Peer Connection Initiated with [AF_INET]????
Thu Mar 08 22:58:58 2018 AUTH: Received control message: AUTH_FAILED
Thu Mar 08 22:58:58 2018 SIGUSR1[soft,auth-failure] received, process restarting

[Antonio Quartulli]

I am still trying to figure out what's the issue here.

When the cipher is an incongruence in the cipher being used, it is expected that the tunnel is still established but then you get all kind of decryption errors.

In this case you also have an AUTH_FAILED error (which is fatal and kills the connection), but I am not even sure it's related to the cipher.

[hunterx1]

The problem is that it's connecting when it shouldn't, and its confusing which side is at fault (server/client). The GCM cipher in the config file is not supported by the VPN server. I can see that it connected through the balloon notification on the win 10 client. I was expecting a handshake error. If this behavior is expected we can close this.

I can't explain the auth fail, but it is a valid password, and only occurs after the initial connection, errors, and reconnect attempt. The 2nd attempt was identical.

This issue isn't causing me any problems, but if you follow this bug thread ​https://community.openvpn.net/openvpn/ticket/1032, you will understand why I tried to swap to GCM, and how I ended up discovering this issue.

[Antonio Quartulli]

thanks for explaining what you expected.
I think this is the way OpenVPN (not just Connect clients) have always operated.

We could turn this ticket into a feature request and see what the others think about it.

But I can see here the main problem is that client and server do not always exchange cipher details - they are just expected to be configured on both sides.

OpenVPN 2.4 comes with a basic cipher negotiation (when installed on both client and server) but this is not enough to assume that this info is always exchanged.

@syzzer what do you think? This ticket was originally filed as an OpenVPN Connect bug, but it's actually a generic OpenVPN design decision that might be improved.