OpenVPN: TLS Error: TLS key negotiation failed to occur within 60 seconds

openvpn

The http://openvpn.net/index.php/open-source/documentation/howto.html page tells that the error is beacuse: "This error indicates that the client was unable to establish a network connection with the server. " But i think that is not the case here.

Here is my configuration:
OpenVPN Server has been installed on a windows 2008 with 10 valid ip addresses. I can ping the OpenVPN ip address from the outside also there's no firewall installed on the server to block the port.

OpenVPN Server Configuration:
local 96.31.90.174
port 1937
proto tcp
dev tun
ca ca.crt
cert server.crt
key server.key
dh dh1024.pem
ifconfig-pool-persist ipp.txt
keepalive 10 120
comp-lzo
persist-key
persist-tun
status openvpn-status.log
verb 3

OpenVPN Client Configuration:
I've installed it on my windows 7 that has no firewall.

client
dev tun
proto tcp
remote 96.31.90.174 1937
resolv-retry infinite
nobind
persist-key
persist-tun
ca ca.crt
cert client1.crt
key client1.key
ns-cert-type server
comp-lzo
verb 3

And here is the Client log:

Tue Dec 08 23:42:06 2009 LZO compression initialized
Tue Dec 08 23:42:06 2009 Control Channel MTU parms [ L:1544 D:140 EF:40 EB:0 ET:
0 EL:0 ]
Tue Dec 08 23:42:06 2009 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:135 ET:
0 EL:0 AF:3/1 ]
Tue Dec 08 23:42:06 2009 Local Options hash (VER=V4): '69109d17'
Tue Dec 08 23:42:06 2009 Expected Remote Options hash (VER=V4): 'c0103fa8'
Tue Dec 08 23:42:06 2009 Attempting to establish TCP connection with 96.31.90.17
4:1937
Tue Dec 08 23:42:06 2009 TCP connection established with 96.31.90.174:1937
Tue Dec 08 23:42:06 2009 Socket Buffers: R=[8192->8192] S=[8192->8192]
Tue Dec 08 23:42:06 2009 TCPv4_CLIENT link local: [undef]
Tue Dec 08 23:42:06 2009 TCPv4_CLIENT link remote: 96.31.90.174:1937
Tue Dec 08 23:42:08 2009 TLS: Initial packet from 96.31.90.174:1937, sid=fdc04dc
5 451dd470
Tue Dec 08 23:43:06 2009 TLS Error: TLS key negotiation failed to occur within 6
0 seconds (check your network connectivity)
Tue Dec 08 23:43:06 2009 TLS Error: TLS handshake failed
Tue Dec 08 23:43:06 2009 Fatal TLS error (check_tls_errors_co), restarting
Tue Dec 08 23:43:06 2009 TCP/UDP: Closing socket
Tue Dec 08 23:43:06 2009 SIGUSR1[soft,tls-error] received, process restarting
Tue Dec 08 23:43:06 2009 Restart pause, 5 second(s)

And here is Server Log: 

Tue Dec 08 15:26:13 2009 ROUTE default_gateway=96.31.90.129
Tue Dec 08 15:26:13 2009 TAP-WIN32 device [Local Area Connection 2] opened: \\.\
Global\{0602F6D1-2000-4C16-B681-3E9FEFE3200D}.tap
Tue Dec 08 15:26:13 2009 TAP-Win32 Driver Version 9.6
Tue Dec 08 15:26:13 2009 TAP-Win32 MTU=1500
Tue Dec 08 15:26:13 2009 Notified TAP-Win32 driver to set a DHCP IP/netmask of 1
0.8.0.1/255.255.255.252 on interface {0602F6D1-2000-4C16-B681-3E9FEFE3200D} [DHC
P-serv: 10.8.0.2, lease-time: 31536000]
Tue Dec 08 15:26:13 2009 Sleeping for 10 seconds...
Tue Dec 08 15:26:23 2009 Successful ARP Flush on interface [21] {0602F6D1-2000-4
C16-B681-3E9FEFE3200D}
Tue Dec 08 15:26:24 2009 C:\WINDOWS\system32\route.exe ADD 10.8.0.0 MASK 255.255
.255.0 10.8.0.2
Tue Dec 08 15:26:24 2009 ROUTE: route addition failed using CreateIpForwardEntry
: The object already exists.   [status=5010 if_index=21]
Tue Dec 08 15:26:24 2009 Route addition via IPAPI failed [adaptive]
Tue Dec 08 15:26:24 2009 Route addition fallback to route.exe
The route addition failed: The object already exists.

Tue Dec 08 15:26:24 2009 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:135 ET:
0 EL:0 AF:3/1 ]
Tue Dec 08 15:26:24 2009 Listening for incoming TCP connection on 96.31.90.174:1
937
Tue Dec 08 15:26:24 2009 Socket Buffers: R=[8192->8192] S=[8192->8192]
Tue Dec 08 15:26:24 2009 TCPv4_SERVER link local (bound): 96.31.90.174:1937
Tue Dec 08 15:26:24 2009 TCPv4_SERVER link remote: [undef]
Tue Dec 08 15:26:25 2009 MULTI: multi_init called, r=256 v=256
Tue Dec 08 15:26:25 2009 IFCONFIG POOL: base=10.8.0.4 size=62
Tue Dec 08 15:26:25 2009 IFCONFIG POOL LIST
Tue Dec 08 15:26:25 2009 MULTI: TCP INIT maxclients=60 maxevents=64
Tue Dec 08 15:26:25 2009 Initialization Sequence Completed
Tue Dec 08 15:26:33 2009 MULTI: multi_create_instance called
Tue Dec 08 15:26:33 2009 Re-using SSL/TLS context
Tue Dec 08 15:26:33 2009 LZO compression initialized
Tue Dec 08 15:26:33 2009 Control Channel MTU parms [ L:1544 D:140 EF:40 EB:0 ET:
0 EL:0 ]
Tue Dec 08 15:26:34 2009 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:135 ET:
0 EL:0 AF:3/1 ]
Tue Dec 08 15:26:34 2009 Local Options hash (VER=V4): 'c0103fa8'
Tue Dec 08 15:26:34 2009 Expected Remote Options hash (VER=V4): '69109d17'
Tue Dec 08 15:26:34 2009 TCP connection established with 62.220.113.29:56336
Tue Dec 08 15:26:34 2009 Socket Buffers: R=[8192->8192] S=[8192->8192]
Tue Dec 08 15:26:34 2009 TCPv4_SERVER link local: [undef]
Tue Dec 08 15:26:34 2009 TCPv4_SERVER link remote: 62.220.113.29:56336
Tue Dec 08 15:26:34 2009 62.220.113.29:56336 TLS: Initial packet from 62.220.113
.29:56336, sid=fa280cbb 89e9998b
Tue Dec 08 15:26:38 2009 MULTI: multi_create_instance called
Tue Dec 08 15:26:38 2009 Re-using SSL/TLS context
Tue Dec 08 15:26:38 2009 LZO compression initialized
Tue Dec 08 15:26:38 2009 Control Channel MTU parms [ L:1544 D:140 EF:40 EB:0 ET:
0 EL:0 ]
Tue Dec 08 15:26:39 2009 Data Channel MTU parms [ L:1544 D:1450 EF:44 EB:135 ET:
0 EL:0 AF:3/1 ]
Tue Dec 08 15:26:39 2009 Local Options hash (VER=V4): 'c0103fa8'
Tue Dec 08 15:26:39 2009 Expected Remote Options hash (VER=V4): '69109d17'
Tue Dec 08 15:26:39 2009 TCP connection established with 81.91.158.242:62068
Tue Dec 08 15:26:39 2009 Socket Buffers: R=[8192->8192] S=[8192->8192]
Tue Dec 08 15:26:39 2009 TCPv4_SERVER link local: [undef]
Tue Dec 08 15:26:39 2009 TCPv4_SERVER link remote: 81.91.158.242:62068
Tue Dec 08 15:26:39 2009 81.91.158.242:62068 TLS: Initial packet from 81.91.158.
242:62068, sid=cc8b77bc 966250fd
Tue Dec 08 15:27:34 2009 62.220.113.29:56336 TLS Error: TLS key negotiation fail
ed to occur within 60 seconds (check your network connectivity)
Tue Dec 08 15:27:34 2009 62.220.113.29:56336 TLS Error: TLS handshake failed
Tue Dec 08 15:27:34 2009 62.220.113.29:56336 Fatal TLS error (check_tls_errors_c
o), restarting
Tue Dec 08 15:27:34 2009 62.220.113.29:56336 SIGUSR1[soft,tls-error] received, c
lient-instance restarting
Tue Dec 08 15:27:34 2009 TCP/UDP: Closing socket
Tue Dec 08 15:27:39 2009 81.91.158.242:62068 TLS Error: TLS key negotiation fail
ed to occur within 60 seconds (check your network connectivity)
Tue Dec 08 15:27:39 2009 81.91.158.242:62068 TLS Error: TLS handshake failed
Tue Dec 08 15:27:39 2009 81.91.158.242:62068 Fatal TLS error (check_tls_errors_c
o), restarting
Tue Dec 08 15:27:39 2009 81.91.158.242:62068 SIGUSR1[soft,tls-error] received, c
lient-instance restarting
Tue Dec 08 15:27:40 2009 TCP/UDP: Closing socket

Best Answer

You have port 1937 specified in your client configuration, but port 1194 specified for the server to listen on in your server config. Having said that, your server log shows that it's listening on port 1937, at least at the time that you took that log. Other than that, nothing looks amiss to me.

It sure looks like you're getting good TCP connections between the client and the server. To rule out any PKI issues, I'd start with a static key configuration and, once that works, move on to a public key configuration.

Related Topic