Hello everyone. I'm a little bit out of ideas, so I hope, maybe someone may have experience with this issue. I'm running a small server with services for a small non-profitable org. Because there is a complicated access and conditions onsite, I'm running there just a little "white horse" server A, with OpenVPN server on it, which is forwarding all the requests to another site. There is a client (server B), automatically connecting to the VPN server (A), hosting all the services. For months, the connection has been stable without any issues, however, a few weeks ago, it started to drop randomly with a strange phenomenon. I can't say what was / is the trigger point, generally for the fault, as well as for the particular drops. I made no significant change or so... The issue itself occurs the way that the VPN connection goes down from the client side (B) (
Inactivity timeout) and when it's trying to recover the connection, it returns with the error "
TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)" and so on and on... It's nice it says to check the network connectivity, however, that is not the issue. What is proven by the fact that restarting the client daemon causes immediately the client to connect successfully. Sometimes, it drops the connection within hours since the restart, sometimes it takes days... What I did to start the troubleshooting, except restarting the related devices on the infrastructure was, that I increased the log levels of the server side (although it does not receive the bad attempts, so the problem is client (B)) as well as of the client side. One of the first error details I caught after that, was that a msg "
Recursive routing detected, drop tun packet to [AF_INET]84.42.x.x:1194" appeared. I tried googling a little and then added the "allow-recursive-routing" to the client config, what caused that these messages disappeared. However the connection is still going down, last time I increased log verbosity to 7 and catching more and more details... Please, if you may have suspicion what could be the cause, put me on the track. It's annoying. Thanks a lot.
client
dev tun
proto udp
remote 84.42.x.x 1194
resolv-retry infinite
nobind
persist-key
persist-tun
remote-cert-tls server
auth SHA512
cipher AES-256-CBC
ignore-unknown-option block-outside-dns
log /var/log/openvpn/client.log
verb 7
allow-recursive-routing
<ca>
certs here...
local 0.0.0.0
port 1194
proto udp
dev tun
ca ca.crt
cert server.crt
key server.key
dh dh.pem
auth SHA512
tls-crypt tc.key
topology subnet
server 10.7.0.0 255.255.255.0
server-ipv6 fddd:1194:1194:1194::/64
client-config-dir /etc/openvpn/server/ccd
push "redirect-gateway def1 ipv6 bypass-dhcp"
push "dhcp-option DOMAIN my-domain.com"
push "dhcp-option DNS 10.7.0.1"
keepalive 10 120
cipher AES-256-CBC
data-ciphers AES-256-CBC
user nobody
group nogroup
persist-key
persist-tun
crl-verify crl.pem
explicit-exit-notify
status openvpn-status.log
log /var/log/openvpn/server.log
verb 5
Drop 1
Aug 01 16:30:09 client openvpn[1696]: VERIFY EKU OK
Aug 01 16:30:09 client openvpn[1696]: VERIFY OK: depth=0, CN=server
Aug 01 16:30:09 client openvpn[1696]: Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Aug 01 16:30:09 client openvpn[1696]: Outgoing Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
Aug 01 16:30:09 client openvpn[1696]: Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Aug 01 16:30:09 client openvpn[1696]: Incoming Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
Aug 01 16:30:09 client openvpn[1696]: Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Aug 01 16:50:03 client openvpn[1696]: [server] Inactivity timeout (--ping-restart), restarting
Aug 01 16:50:03 client openvpn[1696]: SIGUSR1[soft,ping-restart] received, process restarting
Aug 01 16:50:03 client openvpn[1696]: Restart pause, 5 second(s)
Aug 01 16:50:08 client openvpn[1696]: TCP/UDP: Preserving recently used remote address: [AF_INET]84.42.x.x:1194
Aug 01 16:50:08 client openvpn[1696]: Socket Buffers: R=[212992->212992] S=[212992->212992]
Aug 01 16:50:08 client openvpn[1696]: UDP link local: (not bound)
Aug 01 16:50:08 client openvpn[1696]: UDP link remote: [AF_INET]84.42.x.x:1194
Aug 01 16:51:08 client openvpn[1696]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Aug 01 16:51:08 client openvpn[1696]: TLS Error: TLS handshake failed
Aug 01 16:51:08 client openvpn[1696]: SIGUSR1[soft,tls-error] received, process restarting
Aug 01 16:51:08 client openvpn[1696]: Restart pause, 5 second(s)
Aug 01 16:30:09 server openvpn[39472]: client/46.39.x.x:59683 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Aug 01 16:30:09 server openvpn[39472]: client/46.39.x.x:59683 Outgoing Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
Aug 01 16:30:09 server openvpn[39472]: client/46.39.x.x:59683 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Aug 01 16:30:09 server openvpn[39472]: client/46.39.x.x:59683 Incoming Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
Aug 01 16:30:09 server openvpn[39472]: client/46.39.x.x:59683 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Aug 01 16:52:03 server openvpn[39472]: client/46.39.x.x:59683 [client] Inactivity timeout (--ping-restart), restarting
Aug 01 16:52:03 server openvpn[39472]: client/46.39.x.x:59683 SIGUSR1[soft,ping-restart] received, client-instance restarting
Drop 2 (client only)
Sun Aug 14 01:13:24 2022 us=89113 Recursive routing detected, drop tun packet to [AF_INET]84.42.x.x:1194
Sun Aug 14 01:13:25 2022 us=149235 [server] Inactivity timeout (--ping-restart), restarting
Sun Aug 14 01:13:25 2022 us=149418 TCP/UDP: Closing socket
Sun Aug 14 01:13:25 2022 us=149451 SIGUSR1[soft,ping-restart] received, process restarting
Sun Aug 14 01:13:25 2022 us=149478 Restart pause, 5 second(s)
Sun Aug 14 01:13:30 2022 us=149564 Re-using SSL/TLS context
Sun Aug 14 01:13:30 2022 us=149682 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
Sun Aug 14 01:13:30 2022 us=149708 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Sun Aug 14 01:13:30 2022 us=149733 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Sun Aug 14 01:13:30 2022 us=149739 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Sun Aug 14 01:13:30 2022 us=149750 TCP/UDP: Preserving recently used remote address: [AF_INET]84.42.x.x:1194
Sun Aug 14 01:13:30 2022 us=149774 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sun Aug 14 01:13:30 2022 us=149784 UDP link local: (not bound)
Sun Aug 14 01:13:30 2022 us=149790 UDP link remote: [AF_INET]84.42.x.x:1194
WrrrSun Aug 14 01:13:30 2022 us=149994 Recursive routing detected, drop tun packet to [AF_INET]84.42.x.x:1194
rWrSun Aug 14 01:13:32 2022 us=276099 Recursive routing detected, drop tun packet to [AF_INET]84.42.x.x:1194
rWrSun Aug 14 01:13:36 2022 us=319499 Recursive routing detected, drop tun packet to [AF_INET]84.42.x.x:1194
rrrrrrrWrSun Aug 14 01:13:44 2022 us=667422 Recursive routing detected, drop tun packet to [AF_INET]84.42.x.x:1194
rrrrrrrrrWrSun Aug 14 01:14:00 2022 us=174136 Recursive routing detected, drop tun packet to [AF_INET]84.42.x.x:1194
rrrrrrrrrrrrrrrrrrrrrSun Aug 14 01:14:30 2022 us=74325 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Sun Aug 14 01:14:30 2022 us=74356 TLS Error: TLS handshake failed
Sun Aug 14 01:14:30 2022 us=74424 TCP/UDP: Closing socket
Sun Aug 14 01:14:30 2022 us=74449 SIGUSR1[soft,tls-error] received, process restarting
Sun Aug 14 01:14:30 2022 us=74464 Restart pause, 5 second(s)
Sun Aug 14 01:14:35 2022 us=74547 Re-using SSL/TLS context
Sun Aug 14 01:14:35 2022 us=74636 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
Sun Aug 14 01:14:35 2022 us=74653 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Sun Aug 14 01:14:35 2022 us=74675 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Sun Aug 14 01:14:35 2022 us=74681 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Sun Aug 14 01:14:35 2022 us=74690 TCP/UDP: Preserving recently used remote address: [AF_INET]84.42.x.x:1194
Sun Aug 14 01:14:35 2022 us=74714 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sun Aug 14 01:14:35 2022 us=74724 UDP link local: (not bound)
Sun Aug 14 01:14:35 2022 us=74730 UDP link remote: [AF_INET]84.42.x.x:1194
Drop 3 (client only)
Tue Aug 16 14:46:32 2022 us=132676 VERIFY KU OK
Tue Aug 16 14:46:32 2022 us=132686 Validating certificate extended key usage
Tue Aug 16 14:46:32 2022 us=132693 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Tue Aug 16 14:46:32 2022 us=132707 VERIFY EKU OK
Tue Aug 16 14:46:32 2022 us=132713 VERIFY OK: depth=0, CN=server
WRWWWRwrWRRWRTue Aug 16 14:46:32 2022 us=154714 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Tue Aug 16 14:46:32 2022 us=154768 Outgoing Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
Tue Aug 16 14:46:32 2022 us=154777 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key
Tue Aug 16 14:46:32 2022 us=154786 Incoming Data Channel: Using 512 bit message hash 'SHA512' for HMAC authentication
WTue Aug 16 14:46:32 2022 us=154815 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
RwRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwRwrWRwrWRwRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwRwrWRwRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwrWRwr$
Tue Aug 16 14:54:47 2022 us=1079 TCP/UDP: Closing socket
Tue Aug 16 14:54:47 2022 us=1105 SIGUSR1[soft,ping-restart] received, process restarting
Tue Aug 16 14:54:47 2022 us=1123 Restart pause, 5 second(s)
Tue Aug 16 14:54:52 2022 us=1237 Re-using SSL/TLS context
Tue Aug 16 14:54:52 2022 us=1334 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
Tue Aug 16 14:54:52 2022 us=1349 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Tue Aug 16 14:54:52 2022 us=1371 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Tue Aug 16 14:54:52 2022 us=1377 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Tue Aug 16 14:54:52 2022 us=1387 TCP/UDP: Preserving recently used remote address: [AF_INET]84.42.x.x:1194
Tue Aug 16 14:54:52 2022 us=1408 Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue Aug 16 14:54:52 2022 us=1417 UDP link local: (not bound)
Tue Aug 16 14:54:52 2022 us=1423 UDP link remote: [AF_INET]84.42.x.x:1194
WrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrWrrrWrrrrrrrWrrrrrrrrrrrWrrrrrrrrrrrrrrrrrrrrTue Aug 16 14:55:52 2022 us=654834 TLS Error: TLS key negotiation failed to occur within 60 seconds (che$
Tue Aug 16 14:55:52 2022 us=654886 TLS Error: TLS handshake failed
Tue Aug 16 14:55:52 2022 us=654954 TCP/UDP: Closing socket
Tue Aug 16 14:55:52 2022 us=654977 SIGUSR1[soft,tls-error] received, process restarting
Tue Aug 16 14:55:52 2022 us=654991 Restart pause, 5 second(s)
Tue Aug 16 14:55:57 2022 us=655109 Re-using SSL/TLS context
Tue Aug 16 14:55:57 2022 us=655204 Control Channel MTU parms [ L:1621 D:1156 EF:94 EB:0 ET:0 EL:3 ]
Tue Aug 16 14:55:57 2022 us=655221 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Tue Aug 16 14:55:57 2022 us=655242 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-client'
Tue Aug 16 14:55:57 2022 us=655248 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1601,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA512,keysize 256,key-method 2,tls-server'
Tue Aug 16 14:55:57 2022 us=655257 TCP/UDP: Preserving recently used remote address: [AF_INET]84.42.x.x:1194
Tue Aug 16 14:55:57 2022 us=655276 Socket Buffers: R=[212992->212992] S=[212992->212992]
Tue Aug 16 14:55:57 2022 us=655285 UDP link local: (not bound)
Tue Aug 16 14:55:57 2022 us=655291 UDP link remote: [AF_INET]84.42.x.x:1194