[Openvpn-users] intermittent TLS Error: TLS key negotiation failed to occur within 60 seconds

[Jeff P. <jef...@tr...>]

Hello all,

I've been tearing my hair out over this error message for nearly a week. 
I don't know where to go from here as the connection succeeds and does 
work for a while. Then later the connection drops. This leads me to 
believe that it is not a firewall issue and has to be something with 
OpenVPN itself. I've read the FAQ, searched the mailing list archives, 
googled, and I'm still stuck. Any suggestions? Here's the log output:

Wed Jul 12 09:00:46 2006 MULTI: multi_create_instance called
Wed Jul 12 09:00:46 2006 99.99.99.99:1043 Re-using SSL/TLS context
Wed Jul 12 09:00:46 2006 99.99.99.99:1043 LZO compression initialized
Wed Jul 12 09:00:46 2006 99.99.99.99:1043 Control Channel MTU parms [ 
L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Wed Jul 12 09:00:46 2006 99.99.99.99:1043 Data Channel MTU parms [ 
L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Wed Jul 12 09:00:46 2006 99.99.99.99:1043 Local Options hash (VER=V4): 
'530fdded'
Wed Jul 12 09:00:46 2006 99.99.99.99:1043 Expected Remote Options hash 
(VER=V4): '41690919'
Wed Jul 12 09:00:46 2006 99.99.99.99:1043 TLS: Initial packet from 
99.99.99.99:1043, sid=c7bc6638 d11a28c8
Wed Jul 12 09:00:47 2006 99.99.99.99:1043 VERIFY OK: depth=1, 
/C=UK/ST=Lincolnshire/L=Peterborough/O=OpenVPN-bogus/CN=OpenVPN-CA/ema...@bo...
Wed Jul 12 09:00:47 2006 99.99.99.99:1043 VERIFY OK: depth=0, 
/C=UK/ST=Lincolnshire/O=OpenVPN-bogus/CN=user.name/ema...@bo...
Wed Jul 12 09:00:47 2006 99.99.99.99:1043 Data Channel Encrypt: Cipher 
'BF-CBC' initialized with 128 bit key
Wed Jul 12 09:00:47 2006 99.99.99.99:1043 Data Channel Encrypt: Using 
160 bit message hash 'SHA1' for HMAC authentication
Wed Jul 12 09:00:47 2006 99.99.99.99:1043 NOTE: --mute triggered...
Wed Jul 12 09:00:47 2006 99.99.99.99:1043 3 variation(s) on previous 5 
message(s) suppressed by --mute
Wed Jul 12 09:00:47 2006 99.99.99.99:1043 [user.name] Peer Connection 
Initiated with 99.99.99.99:1043
Wed Jul 12 09:00:47 2006 user.name/99.99.99.99:1043 MULTI: Learn: 
10.23.7.18 -> user.name/99.99.99.99:1043
Wed Jul 12 09:00:47 2006 user.name/99.99.99.99:1043 MULTI: primary 
virtual IP for user.name/99.99.99.99:1043: 10.23.7.18
Wed Jul 12 09:00:48 2006 user.name/99.99.99.99:1043 PUSH: Received 
control message: 'PUSH_REQUEST'
Wed Jul 12 09:00:48 2006 user.name/99.99.99.99:1043 SENT CONTROL 
[user.name]: 'PUSH_REPLY,route 10.0.0.0 255.255.255.0,dhcp-option DNS 
10.0.0.2,dhcp-option WINS 10.0.0.2,route 10.23.7.1,ping 10,ping-restart 
30,ifconfig 10.23.7.18 10.23.7.17' (status=1)
Wed Jul 12 09:20:22 2006 MULTI: multi_create_instance called
Wed Jul 12 09:20:22 2006 99.99.99.99:1053 Re-using SSL/TLS context
Wed Jul 12 09:20:22 2006 99.99.99.99:1053 LZO compression initialized
Wed Jul 12 09:20:22 2006 99.99.99.99:1053 Control Channel MTU parms [ 
L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Wed Jul 12 09:20:22 2006 99.99.99.99:1053 Data Channel MTU parms [ 
L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Wed Jul 12 09:20:22 2006 99.99.99.99:1053 Local Options hash (VER=V4): 
'530fdded'
Wed Jul 12 09:20:22 2006 99.99.99.99:1053 Expected Remote Options hash 
(VER=V4): '41690919'
Wed Jul 12 09:20:22 2006 99.99.99.99:1053 TLS: Initial packet from 
99.99.99.99:1053, sid=f8621f71 c966af2f
Wed Jul 12 09:20:54 2006 MULTI: multi_create_instance called
Wed Jul 12 09:20:54 2006 99.99.99.99:1054 Re-using SSL/TLS context
Wed Jul 12 09:20:54 2006 99.99.99.99:1054 LZO compression initialized
Wed Jul 12 09:20:54 2006 99.99.99.99:1054 Control Channel MTU parms [ 
L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Wed Jul 12 09:20:54 2006 99.99.99.99:1054 Data Channel MTU parms [ 
L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Wed Jul 12 09:20:54 2006 99.99.99.99:1054 Local Options hash (VER=V4): 
'530fdded'
Wed Jul 12 09:20:54 2006 99.99.99.99:1054 Expected Remote Options hash 
(VER=V4): '41690919'
Wed Jul 12 09:20:54 2006 99.99.99.99:1054 TLS: Initial packet from 
99.99.99.99:1054, sid=e1f2c082 8fdb173f
Wed Jul 12 09:21:09 2006 user.name/99.99.99.99:1043 [user.name] 
Inactivity timeout (--ping-restart), restarting
Wed Jul 12 09:21:09 2006 user.name/99.99.99.99:1043 
SIGUSR1[soft,ping-restart] received, client-instance restarting
Wed Jul 12 09:21:22 2006 99.99.99.99:1053 TLS Error: TLS key negotiation 
failed to occur within 60 seconds (check your network connectivity)
Wed Jul 12 09:21:22 2006 99.99.99.99:1053 TLS Error: TLS handshake failed
Wed Jul 12 09:21:22 2006 99.99.99.99:1053 SIGUSR1[soft,tls-error] 
received, client-instance restarting
Wed Jul 12 09:21:26 2006 MULTI: multi_create_instance called
Wed Jul 12 09:21:26 2006 99.99.99.99:1055 Re-using SSL/TLS context
Wed Jul 12 09:21:26 2006 99.99.99.99:1055 LZO compression initialized
Wed Jul 12 09:21:26 2006 99.99.99.99:1055 Control Channel MTU parms [ 
L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Wed Jul 12 09:21:26 2006 99.99.99.99:1055 Data Channel MTU parms [ 
L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Wed Jul 12 09:21:26 2006 99.99.99.99:1055 Local Options hash (VER=V4): 
'530fdded'
Wed Jul 12 09:21:26 2006 99.99.99.99:1055 Expected Remote Options hash 
(VER=V4): '41690919'
Wed Jul 12 09:21:26 2006 99.99.99.99:1055 TLS: Initial packet from 
99.99.99.99:1055, sid=759322c1 862cc73e
Wed Jul 12 09:21:54 2006 99.99.99.99:1054 TLS Error: TLS key negotiation 
failed to occur within 60 seconds (check your network connectivity)
Wed Jul 12 09:21:54 2006 99.99.99.99:1054 TLS Error: TLS handshake failed
Wed Jul 12 09:21:54 2006 99.99.99.99:1054 SIGUSR1[soft,tls-error] 
received, client-instance restarting

Obviously the IP has been changed for security reasons. If needed I can 
provide the client and server configs. Thanks in advance.

Jeff