Hi,
I recently upgraded our OpenVPN Access Server from the following set up:
Old
Server 2.0.12
Client 2.0.9.201
New:
Server 2.0.24
Client 2.0.18.203
We now have a situation where people using the old client (2.0.9.201) can connect to our Access Server, but anyone that upgrades their client to 2.0.18.203 cannot connect.
Looking at the logs for a failed connection on the server:
tail -f /var/log/openvpnas.log
2016-01-21 10:11:41+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:11:41 2016 TCP connection established with [AF_INET]<officeIP>:54693'
2016-01-21 10:11:41+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:11:41 2016 <officeIP>:54693 SIGTERM[soft,port-share-redirect] received, client-instance exiting'
2016-01-21 10:11:50+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:11:50 2016 TCP connection established with [AF_INET]<officeIP>:54695'
2016-01-21 10:11:50+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:11:50 2016 <officeIP>:54695 SIGTERM[soft,port-share-redirect] received, client-instance exiting'
2016-01-21 10:11:50+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:11:50 2016 TCP connection established with [AF_INET]<officeIP>:54696'
2016-01-21 10:11:50+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:11:50 2016 <officeIP>:54696 SIGTERM[soft,port-share-redirect] received, client-instance exiting'
2016-01-21 10:11:51+0000 [-] OVPN 3 OUT: 'Thu Jan 21 10:11:51 2016 <officeIP>:49742 TLS: Initial packet from [AF_INET]<officeIP>:49742, sid=b0c90eff 15fd2c83'
...Nagios check...
2016-01-21 10:12:50+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:12:50 2016 TCP connection established with [AF_INET]<officeIP>:54702'
2016-01-21 10:12:50+0000 [-] OVPN 0 OUT: 'Thu Jan 21 10:12:50 2016 <officeIP>:54702 SIGTERM[soft,port-share-redirect] received, client-instance exiting'
2016-01-21 10:12:51+0000 [-] OVPN 3 OUT: 'Thu Jan 21 10:12:51 2016 <officeIP>:49742 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)'
2016-01-21 10:12:51+0000 [-] OVPN 3 OUT: 'Thu Jan 21 10:12:51 2016 <officeIP>:49742 TLS Error: TLS handshake failed'
2016-01-21 10:12:51+0000 [-] OVPN 3 OUT: 'Thu Jan 21 10:12:51 2016 <officeIP>:49742 SIGUSR1[soft,tls-error] received, client-instance restarting'
Checking the logs on my laptop:
tail -f /Library/Application\ Support/OpenVPN/log/openvpn.log
2016-01-21 10:11:41+0000 [HTTPChannel,868,] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_6cG2oyD3jQb58OiD_1', 10] kw={} ret=[{'type': 'PROFILE', 'state': 'connect', 'profile_id': '<remote_vpn_tld>_dynamic_p5718', 'cookie': 'TRAY_CLIENT_cm9uYW4=_oGAVYRS3', 'timestamp': 1453371101}]
2016-01-21 10:11:41+0000 [HTTPChannel,868,] *** API CALL f=xmlrpc_Connect args=[{'new_only': True, 'cookie': 'TRAY_CLIENT_cm9uYW4=_oGAVYRS3', 'profile_id': '<remote_vpn_tld>_dynamic_p5718', 'type': 'dynamic', 'non_interactive': False}, ['STATE', 'PASSWORD', 'ACTIVE', 'CERT_APPROVAL', 'INFO', 'CONNECTED_USER', 'FATAL', 'SCRIPT', 'CHALLENGE', 'DELETE_PENDING', 'NOTIFY', 'RSA_SIGN', 'CONNECT_TIMEOUT', 'BYTECOUNT'], {}] kw={} ret='sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1'
2016-01-21 10:11:41+0000 [HTTPChannel,870,] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'status': 'need', 'timestamp': 1453371101, 'need': ('username', 'password'), 'type': 'PASSWORD', 'auth_type': 'Dynamic'}]
2016-01-21 10:11:43+0000 [HTTPChannel,872,] *** API CALL f=xmlrpc_SubmitCreds args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', {'username': '<remote_vpn_tld>', 'password': '[redacted]'}, 'Dynamic', True] kw={} ret=None
2016-01-21 10:11:43+0000 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 4082
2016-01-21 10:11:43+0000 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x8fb4270>
2016-01-21 10:11:43+0000 [twisted.names.dns.DNSDatagramProtocol (UDP)] *** DNS_ADD <remote_vpn.tld> ['<remote_IP>', 12]
2016-01-21 10:11:43+0000 [twisted.names.dns.DNSDatagramProtocol (UDP)] Updating /etc/hosts with [(u'<remote_vpn.tld>', '<remote_IP>')]
2016-01-21 10:11:43+0000 [-] (Port 4082 Closed)
2016-01-21 10:11:43+0000 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x8fb4270>
2016-01-21 10:11:43+0000 [Uninitialized] OpenSSL web ciphersuites: DEFAULT:!EXP:!PSK:!SRP:!LOW:!RC4
2016-01-21 10:11:43+0000 [XMLProxyQueryProtocol,client] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'timestamp': 1453371103, 'type': 'CHALLENGE', 'value': {'text': 'Enter Google Authenticator Code', 'flags': ['R', 'E'], 'user': u'<username>'}}]
2016-01-21 10:11:52+0000 [HTTPChannel,875,] *** API CALL f=xmlrpc_SubmitChallengeResponse args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', '866471'] kw={} ret=None
2016-01-21 10:11:52+0000 [-] *** DNS_ADD <remote_vpn.tld> [u'<remote_IP>', 12]
2016-01-21 10:11:52+0000 [XMLProxyQueryProtocol,client] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'timestamp': 1453371112, 'info_type': 'DYNAMIC_SUCCEED', 'type': 'INFO', 'severity': 'info', 'value': 'dynamic profile access succeeded'}]
2016-01-21 10:11:52+0000 [-] Profile approve: profile '<remote_vpn.tld>' signed_by=u'domain.tld' was previously seen, approval=True
2016-01-21 10:11:52+0000 [-] OpenVPN <remote_vpn_tld>_dynamic_p5718 instantiated
2016-01-21 10:11:52+0000 [-] pyovpn.client.vpncli.MyOMIServer starting on "u'/Library/Application Support/OpenVPN/sock/ovpn-P6OhGfWAZikY.sock'"
2016-01-21 10:11:52+0000 [-] (Port None Closed)
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u">INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info"
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'>HOLD:Waiting for hold release'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: ['state on']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'SUCCESS: real-time state notification set to ON'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: ['echo on']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'SUCCESS: real-time echo notification set to ON'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: ['bytecount 1']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'SUCCESS: bytecount interval changed'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: ['hold off']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'SUCCESS: hold flag set to OFF'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: ['hold release']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'SUCCESS: hold release succeeded'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] OpenVPN start: name='<remote_vpn_tld>_dynamic_p5718' sev='info' msg='process started successfully'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'active': True, 'timestamp': 1453371112, 'type': 'ACTIVE', 'last': None}]
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u">PASSWORD:Need 'Auth' username/password SC:1,Enter Google Authenticator Code"
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: [u'username "Auth" "<username>"']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u"SUCCESS: 'Auth' username entered, but not yet verified"
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: ['password "Auth" "[redacted]"']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u"SUCCESS: 'Auth' password entered, but not yet verified"
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'>REMOTE:<remote_vpn.tld>,1194,udp'
2016-01-21 10:11:52+0000 [MyOMIClient,0,] TO OMI: ['remote ACCEPT']
2016-01-21 10:11:52+0000 [MyOMIClient,0,] FROM OMI: u'SUCCESS: remote command succeeded'
2016-01-21 10:11:52+0000 [HTTPChannel,877,] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'status': 'cached-response', 'timestamp': 1453371112, 'type': 'PASSWORD', 'auth_type': u'Auth'}]
2016-01-21 10:11:53+0000 [MyOMIClient,0,] FROM OMI: u'>STATE:1453371113,WAIT,,,'
2016-01-21 10:11:53+0000 [MyOMIClient,0,] *** STATE 1453371113,WAIT,,,
2016-01-21 10:11:53+0000 [MyOMIClient,0,] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'timestamp': 1453371113, 'state': u'WAIT', 'type': 'STATE'}]
2016-01-21 10:11:53+0000 [MyOMIClient,0,] FROM OMI: u'>STATE:1453371113,AUTH,,,'
2016-01-21 10:11:53+0000 [MyOMIClient,0,] *** STATE 1453371113,AUTH,,,
2016-01-21 10:11:53+0000 [HTTPChannel,880,] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'timestamp': 1453371113, 'state': u'AUTH', 'type': 'STATE'}]
2016-01-21 10:12:53+0000 [MyOMIClient,0,] FROM OMI: u'>STATE:1453371173,RECONNECTING,tls-error,,'
2016-01-21 10:12:53+0000 [MyOMIClient,0,] *** STATE 1453371173,RECONNECTING,tls-error,,
2016-01-21 10:12:53+0000 [MyOMIClient,0,] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'timestamp': 1453371173, 'state': u'RECONNECTING', 'type': 'STATE', 'reason': u'tls-error'}]
2016-01-21 10:12:53+0000 [-] OpenVPNClient.timeout_handler
2016-01-21 10:12:53+0000 [-] TO OMI: ['exit']
2016-01-21 10:12:53+0000 [MyOMIClient,0,] OMI Cancel pending deferred ['exit']
2016-01-21 10:12:53+0000 [-] *** UPDOWN: unsetdns
2016-01-21 10:12:53+0000 [-] *** SCDynamicStoreSetValue Setup:/Network/Service/AD4D4B5E-78C0-49C7-8CEF-227F49491452/DNS {
2016-01-21 10:12:53+0000 [-] }
2016-01-21 10:12:53+0000 [-] *** SystemConfiguration event sent to 'Setup:/Network/Global/IPv4' for 'VPN down'
2016-01-21 10:12:53+0000 [-] OpenVPN <remote_vpn_tld>_dynamic_p5718 stop: process stopped with exit code 0
2016-01-21 10:12:53+0000 [-] *** API CALL f=xmlrpc_Poll args=['sess_TrackActiveProfiles_6cG2oyD3jQb58OiD_1', 10] kw={} ret=[{'timestamp': 1453371173, 'state': 'disconnect', 'profile_id': '<remote_vpn_tld>_dynamic_p5718', 'type': 'PROFILE'}]
2016-01-21 10:12:53+0000 [HTTPChannel,907,] *** API CALL f=xmlrpc_Poll args=['sess_<remote_vpn_tld>_dynamic_p5718_dyfrfDl5I6UqPnNU_1', 10] kw={} ret=[{'timestamp': 1453371173, 'type': 'CONNECT_TIMEOUT'}, {'active': False, 'timestamp': 1453371173, 'type': 'ACTIVE', 'last': True}, {'timestamp': 1453371173, 'type': 'DELETE_PENDING'}]
2016-01-21 10:13:47+0000 [-] *** DNS_DEL <remote_vpn.tld> [u'<remote_IP>', 0]
2016-01-21 10:13:47+0000 [-] Updating /etc/hosts with []
tail -f /Library/Application\ Support/OpenVPN/log/vpn_domain_tld_dynamic_p5718.log
Thu Jan 21 10:11:52 2016 OpenVPN 2.3_ASC12f i386-apple-darwin10.8.0 [SSL (OpenSSL)] [LZO] [MH] [NOSCRIPTS] [IPv6] built on Oct 4 2015
Thu Jan 21 10:11:52 2016 library versions: OpenSSL 1.0.2d 9 Jul 2015, LZO 2.06
Thu Jan 21 10:11:52 2016 MANAGEMENT: client_uid=0
Thu Jan 21 10:11:52 2016 MANAGEMENT: Connected to management server at /Library/Application Support/OpenVPN/sock/ovpn-P6OhGfWAZikY.sock
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'state on'
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'echo on'
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'bytecount 1'
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'hold off'
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'hold release'
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'username "Auth" "<username>"'
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'password [...]'
Thu Jan 21 10:11:52 2016 MANAGEMENT: CMD 'remote ACCEPT'
Thu Jan 21 10:11:53 2016 Control Channel Authentication: tls-auth using INLINE static key file
Thu Jan 21 10:11:53 2016 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Jan 21 10:11:53 2016 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Jan 21 10:11:53 2016 Socket Buffers: R=[196724->100000] S=[9216->100000]
Thu Jan 21 10:11:53 2016 UDPv4 link local: [undef]
Thu Jan 21 10:11:53 2016 UDPv4 link remote: [AF_INET]<server_ip>:1194
Thu Jan 21 10:11:53 2016 MANAGEMENT: >STATE:1453371113,WAIT,,,
Thu Jan 21 10:11:53 2016 MANAGEMENT: >STATE:1453371113,AUTH,,,
Thu Jan 21 10:11:53 2016 TLS: Initial packet from [AF_INET]<server_ip>:1194, sid=ae74f373 40e01077
Thu Jan 21 10:12:53 2016 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Thu Jan 21 10:12:53 2016 TLS Error: TLS handshake failed
Thu Jan 21 10:12:53 2016 SIGUSR1[soft,tls-error] received, process restarting
Thu Jan 21 10:12:53 2016 MANAGEMENT: >STATE:1453371173,RECONNECTING,tls-error,,
Thu Jan 21 10:12:53 2016 Restart pause, 2 second(s)
Thu Jan 21 10:12:53 2016 MANAGEMENT: CMD 'exit'
Thu Jan 21 10:12:53 2016 MANAGEMENT: Client disconnected
Thu Jan 21 10:12:53 2016 MANAGEMENT: Triggering management exit
Thu Jan 21 10:12:53 2016 SIGTERM[soft,management-exit] received, process exiting
Thu Jan 21 10:12:53 2016 MANAGEMENT: >STATE:1453371173,EXITING,management-exit,,
So it looks like the well documented error: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
https://community.openvpn.net/openvpn/wiki/253-tls-error-tls-key-negotiation-failed-to-occur-within-60-seconds-check-your-network-connectivity
Plenty of forum topics on this and I am continuing to dig through them. I can confirm nothing has changed on our firewall, I do not have a firewall enabled myself on the laptop.
Any help would be appreciated.
R.
