cptdondo
I've been running OpenVPN for a number of years. I have two servers that get incoming client connections, from about 7 clients. Here's where it gets weird:
About a month ago, ALL incoming client connections started timing out with the "TLS key negotiation failed to occur within 60 seconds" message. As these are fairly low-importance tunnels I haven't really tried to sort this out until today. I am stumped; NOTHING I do changes the behavior.
Here's a snippet from one server:
Oct 28 18:14:28 selene ovpn-server-udp[17188]: 218.40.183.241:60146 TLS Error: TLS handshake failed
Oct 28 18:14:28 selene ovpn-server-udp[17188]: 107.200.85.18:52971 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:28 selene ovpn-server-udp[17188]: 107.200.85.18:52971 TLS Error: TLS handshake failed
Oct 28 18:14:30 selene ovpn-server-udp[17188]: 71.226.103.5:47038 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:30 selene ovpn-server-udp[17188]: 71.226.103.5:47038 TLS Error: TLS handshake failed
Oct 28 18:14:30 selene ovpn-server-udp[17188]: 107.200.85.18:42335 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:30 selene ovpn-server-udp[17188]: 107.200.85.18:42335 TLS Error: TLS handshake failed
Oct 28 18:14:30 selene ovpn-server-udp[17188]: 218.40.183.241:56507 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:30 selene ovpn-server-udp[17188]: 218.40.183.241:56507 TLS Error: TLS handshake failed
Oct 28 18:14:32 selene ovpn-server-udp[17188]: 67.237.58.53:36262 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:32 selene ovpn-server-udp[17188]: 67.237.58.53:36262 TLS Error: TLS handshake failed
Oct 28 18:14:32 selene ovpn-server-udp[17188]: 107.200.85.18:43689 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:32 selene ovpn-server-udp[17188]: 107.200.85.18:43689 TLS Error: TLS handshake failed
Oct 28 18:14:33 selene ovpn-server-udp[17188]: 71.226.103.5:37996 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:33 selene ovpn-server-udp[17188]: 71.226.103.5:37996 TLS Error: TLS handshake failed
Oct 28 18:14:34 selene ovpn-server-udp[17188]: 107.200.85.18:39034 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:34 selene ovpn-server-udp[17188]: 107.200.85.18:39034 TLS Error: TLS handshake failed
Oct 28 18:14:35 selene ovpn-server-udp[17188]: 218.40.183.241:36495 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:35 selene ovpn-server-udp[17188]: 218.40.183.241:36495 TLS Error: TLS handshake failed
Oct 28 18:14:35 selene ovpn-server-udp[17188]: 67.237.58.53:54390 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Oct 28 18:14:35 selene ovpn-server-udp[17188]: 67.237.58.53:54390 TLS Error: TLS handshake failed
This happens on both TCP and UDP connections, however no other service is impacted. Everything else works fine.
Here's the config file for one of the TAP servers:
ca /etc/openvpn/ca.crt
cert /etc/openvpn/keys/tap_server.crt
client-config-dir /etc/openvpn/client-tap
dev tap0
dh /etc/openvpn/dh1024.pem
keepalive 10 60
key /etc/openvpn/keys/tap_server.key
mode server
mssfix 1420
port 1196
proto udp
route 192.168.4.152 255.255.255.255
script-security 2
server-bridge 192.168.4.151 255.255.255.0 192.168.4.152 192.168.4.168
status /tmp/openvpn-tap.log
verb 5
up /etc/openvpn/routeup
and here's the log file from that server instance:
Sat Oct 28 18:16:48 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:37779 SIGUSR1[soft,tls-error] received, client-instance restarting
Sat Oct 28 18:16:50 2017 daemon.notice openvpn(tap_server)[2255]: MULTI: multi_create_instance called
Sat Oct 28 18:16:50 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:35137 Re-using SSL/TLS context
Sat Oct 28 18:16:50 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:35137 Control Channel MTU parms [ L:1573 D:138 EF:38 EB:0 ET:0 EL:0 ]
Sat Oct 28 18:16:50 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:35137 Data Channel MTU parms [ L:1573 D:1420 EF:41 EB:4 ET:32 EL:0 ]
Sat Oct 28 18:16:50 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:35137 TLS: Initial packet from [AF_INET]73.81.17.116:35137, sid=d26a34a1 d5339830
Sat Oct 28 18:16:50 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:33006 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Oct 28 18:16:50 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:33006 TLS Error: TLS handshake failed
Sat Oct 28 18:16:50 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:33006 SIGUSR1[soft,tls-error] received, client-instance restarting
Sat Oct 28 18:16:52 2017 daemon.notice openvpn(tap_server)[2255]: MULTI: multi_create_instance called
Sat Oct 28 18:16:52 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45323 Re-using SSL/TLS context
Sat Oct 28 18:16:52 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45323 Control Channel MTU parms [ L:1573 D:138 EF:38 EB:0 ET:0 EL:0 ]
Sat Oct 28 18:16:52 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45323 Data Channel MTU parms [ L:1573 D:1420 EF:41 EB:4 ET:32 EL:0 ]
Sat Oct 28 18:16:52 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45323 TLS: Initial packet from [AF_INET]73.81.17.116:45323, sid=6f9122ef 4c7053cd
Sat Oct 28 18:16:53 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:47812 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Oct 28 18:16:53 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:47812 TLS Error: TLS handshake failed
Sat Oct 28 18:16:53 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:47812 SIGUSR1[soft,tls-error] received, client-instance restarting
Sat Oct 28 18:16:55 2017 daemon.notice openvpn(tap_server)[2255]: MULTI: multi_create_instance called
Sat Oct 28 18:16:55 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:43219 Re-using SSL/TLS context
Sat Oct 28 18:16:55 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:43219 Control Channel MTU parms [ L:1573 D:138 EF:38 EB:0 ET:0 EL:0 ]
Sat Oct 28 18:16:55 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:43219 Data Channel MTU parms [ L:1573 D:1420 EF:41 EB:4 ET:32 EL:0 ]
Sat Oct 28 18:16:55 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:43219 TLS: Initial packet from [AF_INET]73.81.17.116:43219, sid=d6613577 45925a87
Sat Oct 28 18:16:55 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:43756 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Oct 28 18:16:55 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:43756 TLS Error: TLS handshake failed
Sat Oct 28 18:16:55 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:43756 SIGUSR1[soft,tls-error] received, client-instance restarting
Sat Oct 28 18:16:57 2017 daemon.notice openvpn(tap_server)[2255]: MULTI: multi_create_instance called
Sat Oct 28 18:16:57 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45557 Re-using SSL/TLS context
Sat Oct 28 18:16:57 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45557 Control Channel MTU parms [ L:1573 D:138 EF:38 EB:0 ET:0 EL:0 ]
Sat Oct 28 18:16:57 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45557 Data Channel MTU parms [ L:1573 D:1420 EF:41 EB:4 ET:32 EL:0 ]
Sat Oct 28 18:16:57 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:45557 TLS: Initial packet from [AF_INET]73.81.17.116:45557, sid=a6d68f2a 40ed734b
Sat Oct 28 18:16:58 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:38946 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Oct 28 18:16:58 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:38946 TLS Error: TLS handshake failed
Sat Oct 28 18:16:58 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:38946 SIGUSR1[soft,tls-error] received, client-instance restarting
Sat Oct 28 18:17:00 2017 daemon.notice openvpn(tap_server)[2255]: MULTI: multi_create_instance called
Sat Oct 28 18:17:00 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:34245 Re-using SSL/TLS context
Sat Oct 28 18:17:00 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:34245 Control Channel MTU parms [ L:1573 D:138 EF:38 EB:0 ET:0 EL:0 ]
Sat Oct 28 18:17:00 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:34245 Data Channel MTU parms [ L:1573 D:1420 EF:41 EB:4 ET:32 EL:0 ]
Sat Oct 28 18:17:00 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:34245 TLS: Initial packet from [AF_INET]73.81.17.116:34245, sid=eb42eb4e a5486184
Sat Oct 28 18:17:00 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:38400 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Oct 28 18:17:00 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:38400 TLS Error: TLS handshake failed
Sat Oct 28 18:17:00 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:38400 SIGUSR1[soft,tls-error] received, client-instance restarting
Sat Oct 28 18:17:02 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:41814 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sat Oct 28 18:17:02 2017 daemon.err openvpn(tap_server)[2255]: 73.81.17.116:41814 TLS Error: TLS handshake failed
Sat Oct 28 18:17:02 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:41814 SIGUSR1[soft,tls-error] received, client-instance restarting
Sat Oct 28 18:17:02 2017 daemon.notice openvpn(tap_server)[2255]: MULTI: multi_create_instance called
Sat Oct 28 18:17:02 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:39966 Re-using SSL/TLS context
Sat Oct 28 18:17:02 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:39966 Control Channel MTU parms [ L:1573 D:138 EF:38 EB:0 ET:0 EL:0 ]
Sat Oct 28 18:17:02 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:39966 Data Channel MTU parms [ L:1573 D:1420 EF:41 EB:4 ET:32 EL:0 ]
Sat Oct 28 18:17:02 2017 daemon.notice openvpn(tap_server)[2255]: 73.81.17.116:39966 TLS: Initial packet from [AF_INET]73.81.17.116:39966, sid=b71de077 da246e6d
I've ripped apart the firewall and made sure the routing is correct and that everything is working.
tcpdump shows packets going back and forth.
root@AP1:/tmp/etc# tcpdump -i eth0.9 port 1196
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0.9, link-type EN10MB (Ethernet), capture size 65535 bytes
18:19:03.051331 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.47219: UDP, length 114
18:19:03.051438 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.37056: UDP, length 114
18:19:03.051507 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42456: UDP, length 114
18:19:03.051582 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.37237: UDP, length 114
18:19:03.051654 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.40098: UDP, length 114
18:19:03.051720 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.41127: UDP, length 114
18:19:03.051855 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.38082: UDP, length 114
18:19:03.051919 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.35309: UDP, length 114
18:19:03.897716 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 14
18:19:03.898602 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 26
18:19:03.949374 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 114
18:19:03.949381 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 76
18:19:03.949382 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 22
18:19:03.949734 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 22
18:19:03.980902 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 22
18:19:03.981004 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:03.981060 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:03.981130 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:03.981183 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:04.037271 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 22
18:19:04.037275 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 22
18:19:04.037623 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:04.037729 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:04.037808 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42456: UDP, length 114
18:19:04.037876 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.41127: UDP, length 114
18:19:04.040293 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 22
18:19:04.040684 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:04.045380 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 22
18:19:04.045833 IP 104.158.167.35.1196 > c-73-81-17-116.hsd1.pa.comcast.net.42696: UDP, length 114
18:19:04.057525 IP 104.158.167.35.1196 > softbank126041243068.bbtec.net.1196: UDP, length 114
18:19:04.091772 IP c-73-81-17-116.hsd1.pa.comcast.net.42696 > 104.158.167.35.1196: UDP, length 22
Any ideas on where to look?
