openVPN stopped working: TLS key negotiation failed

neubert

Dear community,

had two perfectly working openVPN connections from one client (a dynamic cloud server instance running CentOS 7) to two different servers (IPFire 2.17.99).

I stopped working today. The problem is on the client since I can still connect from my Android phone.

Please see below for logs. Client and server times are in sync. Ping latency is about 60ms. We see that the client is able to initiate a connection to the server. But the TLS handshake fails. After some time we see the infamous ACK output sequence broken message in the server log.

A reboot of the client did not help. An attempt with a new client certificate did not work either.

Searching the web I found some mentioning of the problem, mostly related to wrong configuration or network issues. In my case, no configuration change was done.

The problem may or may not be related to an update of some CentOS 7 packages on the client.

Some week ago I had the same problem at once and I only managed to solve it by throwing the CentOS 7 client installation away and re-installing the entire OS.

I have no clue where else to look for the cause of the problem.

Any help would be greatly appreciated.

Kind regards,
Boris

Client config:

tls-client
client
nobind
dev vpn-bnuv
dev-type tun
proto udp
tun-mtu 1400
remote SERVERFQDN 1194
pkcs12 /etc/openvpn/bnuv.p12
cipher AES-256-CBC
auth SHA1
comp-lzo
verb 6
ns-cert-type server

Client log:

Thu Mar 24 20:36:45 2016 us=752145 OpenVPN 2.3.10 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Jan  4 2016
Thu Mar 24 20:36:45 2016 us=752156 library versions: OpenSSL 1.0.1e-fips 11 Feb 2013, LZO 2.06
Thu Mar 24 20:36:45 2016 us=755815 WARNING: file 's1test.p12' is group or others accessible
Thu Mar 24 20:36:45 2016 us=755903 LZO compression initialized
Thu Mar 24 20:36:45 2016 us=755917 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400)
Thu Mar 24 20:36:45 2016 us=755962 Control Channel MTU parms [ L:1458 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Mar 24 20:36:45 2016 us=755991 Socket Buffers: R=[212992->212992] S=[212992->212992]
Thu Mar 24 20:36:45 2016 us=757230 Data Channel MTU parms [ L:1458 D:1450 EF:58 EB:143 ET:0 EL:3 AF:3/1 ]
Thu Mar 24 20:36:45 2016 us=757257 Local Options String: 'V4,dev-type tun,link-mtu 1458,tun-mtu 1400,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Thu Mar 24 20:36:45 2016 us=757264 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1458,tun-mtu 1400,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Thu Mar 24 20:36:45 2016 us=757286 Local Options hash (VER=V4): '4355902f'
Thu Mar 24 20:36:45 2016 us=757296 Expected Remote Options hash (VER=V4): 'fa437c7c'
Thu Mar 24 20:36:45 2016 us=757307 UDPv4 link local: [undef]
Thu Mar 24 20:36:45 2016 us=757317 UDPv4 link remote: [AF_INET]SERVERIP:1194
Thu Mar 24 20:36:45 2016 us=757350 UDPv4 WRITE [14] to [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Thu Mar 24 20:36:47 2016 us=885721 UDPv4 WRITE [14] to [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Thu Mar 24 20:36:47 2016 us=944077 UDPv4 READ [22] from [AF_INET]SERVERIP:1194: P_ACK_V1 kid=0 [ 0 ]
Thu Mar 24 20:36:47 2016 us=944102 TLS Error: Unroutable control packet received from [AF_INET]SERVERIP:1194 (si=3 op=P_ACK_V1)
Thu Mar 24 20:36:51 2016 us=136456 UDPv4 WRITE [14] to [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Thu Mar 24 20:36:59 2016 us=797676 UDPv4 WRITE [14] to [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Thu Mar 24 20:37:15 2016 us=772509 UDPv4 WRITE [14] to [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Thu Mar 24 20:37:45 2016 us=106108 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Thu Mar 24 20:37:45 2016 us=106172 TLS Error: TLS handshake failed
Thu Mar 24 20:37:45 2016 us=106362 TCP/UDP: Closing socket
Thu Mar 24 20:37:45 2016 us=106415 SIGUSR1[soft,tls-error] received, process restarting
Thu Mar 24 20:37:45 2016 us=106431 Restart pause, 2 second(s)
Thu Mar 24 20:37:47 2016 us=110045 WARNING: file 's1test.p12' is group or others accessible
Thu Mar 24 20:37:47 2016 us=110148 LZO compression initialized
Thu Mar 24 20:37:47 2016 us=110161 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400)
Thu Mar 24 20:37:47 2016 us=110207 Control Channel MTU parms [ L:1458 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Mar 24 20:37:47 2016 us=110238 Socket Buffers: R=[212992->212992] S=[212992->212992]
Thu Mar 24 20:37:47 2016 us=111934 Data Channel MTU parms [ L:1458 D:1450 EF:58 EB:143 ET:0 EL:3 AF:3/1 ]
Thu Mar 24 20:37:47 2016 us=111960 Local Options String: 'V4,dev-type tun,link-mtu 1458,tun-mtu 1400,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Thu Mar 24 20:37:47 2016 us=111966 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1458,tun-mtu 1400,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Thu Mar 24 20:37:47 2016 us=111980 Local Options hash (VER=V4): '4355902f'
Thu Mar 24 20:37:47 2016 us=111989 Expected Remote Options hash (VER=V4): 'fa437c7c'
Thu Mar 24 20:37:47 2016 us=111996 UDPv4 link local: [undef]
Thu Mar 24 20:37:47 2016 us=112004 UDPv4 link remote: [AF_INET]SERVERIP:1194
Thu Mar 24 20:37:47 2016 us=112030 UDPv4 WRITE [14] to [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Thu Mar 24 20:37:49 2016 us=300449 UDPv4 WRITE [14] to [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Thu Mar 24 20:37:49 2016 us=518645 UDPv4 READ [26] from [AF_INET]SERVERIP:1194: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Thu Mar 24 20:37:49 2016 us=518691 TLS: Initial packet from [AF_INET]SERVERIP:1194, sid=17dac22a c7e27c82
Thu Mar 24 20:37:49 2016 us=518737 UDPv4 WRITE [22] to [AF_INET]SERVERIP:1194: P_ACK_V1 kid=0 [ 0 ]
Thu Mar 24 20:37:49 2016 us=518822 UDPv4 WRITE [257] to [AF_INET]SERVERIP:1194: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=243
Thu Mar 24 20:37:49 2016 us=969891 UDPv4 READ [126] from [AF_INET]SERVERIP:1194: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA len=100
Thu Mar 24 20:37:49 2016 us=970084 UDPv4 WRITE [22] to [AF_INET]SERVERIP:1194: P_ACK_V1 kid=0 [ 1 ]
Thu Mar 24 20:37:58 2016 us=352431 UDPv4 READ [114] from [AF_INET]SERVERIP:1194: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=100
Thu Mar 24 20:37:58 2016 us=352525 UDPv4 WRITE [22] to [AF_INET]SERVERIP:1194: P_ACK_V1 kid=0 [ 4 ]

Server log:

Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 Re-using SSL/TLS context
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 LZO compression initialized
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400)
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 MTU DYNAMIC mtu=0, flags=1, 0 -> 138
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Mar 24 20:36:45 SERVERNAME last message repeated 3 times
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 Control Channel MTU parms [ L:1458 D:138 EF:38 EB:0 ET:0 EL:0 ]
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 MTU DYNAMIC mtu=1450, flags=2, 1458 -> 1450
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 Data Channel MTU parms [ L:1458 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 Local Options String: 'V4,dev-type tun,link-mtu 1458,tun-mtu 1400,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1458,tun-mtu 1400,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 Local Options hash (VER=V4): 'fa437c7c'
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 Expected Remote Options hash (VER=V4): '4355902f'
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 SENT PING
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 GET INST BY REAL: CLIENTIP:44871 [created]
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 READ [14] from [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 TLS: Initial packet from [AF_INET]CLIENTIP:44871, sid=510ce560 33bcf683
Mar 24 20:36:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [26] to [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Mar 24 20:36:46 SERVERNAME openvpnserver[2365]: MULTI: REAP range 224 -> 240
Mar 24 20:36:47 SERVERNAME openvpnserver[2365]: MULTI: REAP range 240 -> 256
Mar 24 20:36:47 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [14] to [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:36:47 SERVERNAME openvpnserver[2365]: GET INST BY REAL: CLIENTIP:44871 [succeeded]
Mar 24 20:36:47 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 READ [14] from [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:36:47 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [22] to [AF_INET]CLIENTIP:44871: P_ACK_V1 kid=0 [ 0 ]
Mar 24 20:36:49 SERVERNAME openvpnserver[2365]: MULTI: REAP range 0 -> 16
Mar 24 20:36:50 SERVERNAME openvpnserver[2365]: MULTI: REAP range 16 -> 32
Mar 24 20:36:51 SERVERNAME openvpnserver[2365]: MULTI: REAP range 32 -> 48
Mar 24 20:36:51 SERVERNAME openvpnserver[2365]: GET INST BY REAL: CLIENTIP:44871 [succeeded]
Mar 24 20:36:51 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 READ [14] from [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:36:51 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [26] to [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
Mar 24 20:36:52 SERVERNAME openvpnserver[2365]: MULTI: REAP range 48 -> 64
Mar 24 20:36:52 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 SENT PING
Mar 24 20:36:53 SERVERNAME openvpnserver[2365]: MULTI: REAP range 64 -> 80
Mar 24 20:36:54 SERVERNAME openvpnserver[2365]: MULTI: REAP range 80 -> 96
Mar 24 20:36:55 SERVERNAME openvpnserver[2365]: MULTI: REAP range 96 -> 112
Mar 24 20:36:56 SERVERNAME openvpnserver[2365]: MULTI: REAP range 112 -> 128
Mar 24 20:36:57 SERVERNAME openvpnserver[2365]: MULTI: REAP range 128 -> 144
Mar 24 20:36:58 SERVERNAME openvpnserver[2365]: MULTI: REAP range 144 -> 160
Mar 24 20:36:58 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 UDPv4 WRITE [14] to [AF_INET]CLIENTIP:47878: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:36:59 SERVERNAME openvpnserver[2365]: MULTI: REAP range 160 -> 176
Mar 24 20:36:59 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [14] to [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:36:59 SERVERNAME openvpnserver[2365]: GET INST BY REAL: CLIENTIP:44871 [succeeded]
Mar 24 20:36:59 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 READ [14] from [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:36:59 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [22] to [AF_INET]CLIENTIP:44871: P_ACK_V1 kid=0 [ 0 ]
Mar 24 20:37:00 SERVERNAME openvpnserver[2365]: MULTI: REAP range 176 -> 192
Mar 24 20:37:01 SERVERNAME openvpnserver[2365]: MULTI: REAP range 192 -> 208
Mar 24 20:37:02 SERVERNAME openvpnserver[2365]: MULTI: REAP range 208 -> 224
Mar 24 20:37:03 SERVERNAME openvpnserver[2365]: MULTI: REAP range 224 -> 240
Mar 24 20:37:04 SERVERNAME openvpnserver[2365]: MULTI: REAP range 240 -> 256
Mar 24 20:37:05 SERVERNAME openvpnserver[2365]: MULTI: REAP range 0 -> 16
Mar 24 20:37:06 SERVERNAME openvpnserver[2365]: MULTI: REAP range 16 -> 32
Mar 24 20:37:07 SERVERNAME openvpnserver[2365]: MULTI: REAP range 32 -> 48
Mar 24 20:37:08 SERVERNAME openvpnserver[2365]: MULTI: REAP range 48 -> 64
Mar 24 20:37:08 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 SENT PING
Mar 24 20:37:09 SERVERNAME openvpnserver[2365]: MULTI: REAP range 64 -> 80
Mar 24 20:37:09 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 SENT PING
Mar 24 20:37:10 SERVERNAME openvpnserver[2365]: MULTI: REAP range 80 -> 96
Mar 24 20:37:11 SERVERNAME openvpnserver[2365]: MULTI: REAP range 96 -> 112
Mar 24 20:37:12 SERVERNAME openvpnserver[2365]: MULTI: REAP range 112 -> 128
Mar 24 20:37:13 SERVERNAME openvpnserver[2365]: MULTI: REAP range 128 -> 144
Mar 24 20:37:14 SERVERNAME openvpnserver[2365]: MULTI: REAP range 144 -> 160
Mar 24 20:37:16 SERVERNAME openvpnserver[2365]: MULTI: REAP range 160 -> 176
Mar 24 20:37:16 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [14] to [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:37:16 SERVERNAME openvpnserver[2365]: GET INST BY REAL: CLIENTIP:44871 [succeeded]
Mar 24 20:37:16 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 READ [14] from [AF_INET]CLIENTIP:44871: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
Mar 24 20:37:16 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 UDPv4 WRITE [22] to [AF_INET]CLIENTIP:44871: P_ACK_V1 kid=0 [ 0 ]
Mar 24 20:37:17 SERVERNAME openvpnserver[2365]: MULTI: REAP range 176 -> 192
Mar 24 20:37:18 SERVERNAME openvpnserver[2365]: MULTI: REAP range 192 -> 208
Mar 24 20:37:18 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 SENT PING
Mar 24 20:37:19 SERVERNAME openvpnserver[2365]: MULTI: REAP range 208 -> 224
Mar 24 20:37:20 SERVERNAME openvpnserver[2365]: MULTI: REAP range 224 -> 240
Mar 24 20:37:21 SERVERNAME openvpnserver[2365]: MULTI: REAP range 240 -> 256
Mar 24 20:37:22 SERVERNAME openvpnserver[2365]: MULTI: REAP range 0 -> 16
Mar 24 20:37:23 SERVERNAME openvpnserver[2365]: MULTI: REAP range 16 -> 32
Mar 24 20:37:24 SERVERNAME openvpnserver[2365]: MULTI: REAP range 32 -> 48
Mar 24 20:37:25 SERVERNAME openvpnserver[2365]: MULTI: REAP range 48 -> 64
Mar 24 20:37:26 SERVERNAME openvpnserver[2365]: MULTI: REAP range 64 -> 80
Mar 24 20:37:26 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 SENT PING
Mar 24 20:37:27 SERVERNAME openvpnserver[2365]: MULTI: REAP range 80 -> 96
Mar 24 20:37:28 SERVERNAME openvpnserver[2365]: MULTI: REAP range 96 -> 112
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 SENT PING
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 TLS Error: TLS handshake failed
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 PID packet_id_free
Mar 24 20:37:29 SERVERNAME last message repeated 2 times
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: CLIENTIP:47878 SIGUSR1[soft,tls-error] received, client-instance restarting
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: MULTI: multi_close_instance called
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: PID packet_id_free
Mar 24 20:37:29 SERVERNAME last message repeated 8 times
Mar 24 20:37:29 SERVERNAME openvpnserver[2365]: MULTI: REAP range 112 -> 128
Mar 24 20:37:30 SERVERNAME openvpnserver[2365]: MULTI: REAP range 128 -> 144
Mar 24 20:37:31 SERVERNAME openvpnserver[2365]: MULTI: REAP range 144 -> 160
Mar 24 20:37:32 SERVERNAME openvpnserver[2365]: MULTI: REAP range 160 -> 176
Mar 24 20:37:33 SERVERNAME openvpnserver[2365]: MULTI: REAP range 176 -> 192
Mar 24 20:37:34 SERVERNAME openvpnserver[2365]: MULTI: REAP range 192 -> 208
Mar 24 20:37:35 SERVERNAME openvpnserver[2365]: MULTI: REAP range 208 -> 224
Mar 24 20:37:37 SERVERNAME openvpnserver[2365]: MULTI: REAP range 224 -> 240
Mar 24 20:37:37 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 SENT PING
Mar 24 20:37:38 SERVERNAME openvpnserver[2365]: MULTI: REAP range 240 -> 256
Mar 24 20:37:39 SERVERNAME openvpnserver[2365]: MULTI: REAP range 0 -> 16
Mar 24 20:37:40 SERVERNAME openvpnserver[2365]: MULTI: REAP range 16 -> 32
Mar 24 20:37:41 SERVERNAME openvpnserver[2365]: MULTI: REAP range 32 -> 48
Mar 24 20:37:43 SERVERNAME openvpnserver[2365]: MULTI: REAP range 48 -> 64
Mar 24 20:37:44 SERVERNAME openvpnserver[2365]: MULTI: REAP range 64 -> 80
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: MULTI: REAP range 80 -> 96
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 TLS Error: TLS handshake failed
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 PID packet_id_free
Mar 24 20:37:45 SERVERNAME last message repeated 2 times
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 PID packet_id_init tcp_mode=0 seq_backtrack=64 time_backtrack=15
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: CLIENTIP:44871 SIGUSR1[soft,tls-error] received, client-instance restarting
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: MULTI: multi_close_instance called
Mar 24 20:37:45 SERVERNAME openvpnserver[2365]: PID packet_id_free

Mar 24 20:43:33 SERVERNAME openvpnserver[2365]: CLIENTIP:39753 ACK output sequence broken: [5] 1 3

Traffic

Server config please :roll:

neubert

Traffic wroteServer config please

OpenVPN Server conf

daemon openvpnserver
writepid /var/run/openvpn.pid
;local SERVERFQDN
dev tun
proto udp
port 1194
script-security 3 system
ifconfig-pool-persist /var/ipfire/ovpn/ovpn-leases.db 3600
client-config-dir /var/ipfire/ovpn/ccd
tls-server
ca /var/ipfire/ovpn/ca/cacert.pem
cert /var/ipfire/ovpn/certs/servercert.pem
key /var/ipfire/ovpn/certs/serverkey.pem
dh /var/ipfire/ovpn/ca/dh1024.pem
server XXX.XXX.39.0 255.255.255.0
tun-mtu 1400
route XXX.XXX.38.0 255.255.255.0
keepalive 10 60
status-version 1
status /var/run/ovpnserver.log 30
cipher AES-256-CBC
auth SHA1
comp-lzo
push "dhcp-option DNS XXX.XXX.31.1"
max-clients 100
tls-verify /usr/lib/openvpn/verify
crl-verify /var/ipfire/ovpn/crls/cacrl.pem
user nobody
group nobody
persist-key
persist-tun
verb 7

Traffic

Considering the distinct lack of details you provide, I presume you do not want any help ..

neubert

Sorry, I do not understand what more details I should provide apart from the information given in the initial posting, client and server logs and configuration. Please let me know what else is required to track down the cause of the issue.

Traffic

neubert wroteclient-config-dir /var/ipfire/ovpn/ccd

ccd file details

neubert wroteserver XXX.XXX.39.0 255.255.255.0

is this a suitable address

neubert wrotetun-mtu 1400

do you need this

neubert wrotemax-clients 100

I presume your client is not number 101 ..

neubert wrotetls-verify /usr/lib/openvpn/verify

does this work

neubert wrotecrl-verify /var/ipfire/ovpn/crls/cacrl.pem

is your client revoked

neubert wroteverb 7

verb 4 is sufficient

neubert wroteClient log:
Thu Mar 24 20:36:47 2016 us=944102 TLS Error: Unroutable control packet received from AF_INET]SERVERIP:1194 (si=3 op=P_ACK_V1)

I would say this is important.

One question, does your client have ethernet and wifi connections ?

neubert

All right. Before we go for the deep dive (details below), some background information and surprise.

The openVPN client is a cloud server under my control that runs CentOS 7. It is used for offsite backups of my personal data at home as well as for work-related data at the office. Home and office are connected to the internet via DSL. The DSL routers at each location forward UDP port 1194 to the inner firewalls running IPFire. The server configuration shown in this thread is auto-generated from the IPFire web UI. The client keeps permanent VPN connections to the external IPs of home and office respectively.

There was no system update neither on the client nor on the IPFire openVPN servers before or during the outage, as I can confirm from the logs.

Before creating my initial post yesterday, I restarted the openVPN client connections. They kept on trying the TLS handshake with the openVPN servers at home and office, respectively. Some hours later, overnight, there have been several successful connections to the office and the home location. At about 4:30, the first successful connection to the home location is recorded in the logs. This point in time is unrelated to the reconnection of the internet uplink (occured at 5:09, new external IP was propagated and available to DNS servers around 6:30).

The VPN connection to home is restarted once in a while since then. The client log show:

Mar 25 10:42:43 s1 openvpn[11615]: TLS: tls_process: killed expiring key

every 30 minutes.

One might be lead to think of network issues. But what network issues? SSH connections have been successful, but this is TCP. What comes to my mind is that, from time to time, I have difficulties to reach the DNS server running on the client. Which uses a UDP protocol, like openVPN. I will try and learn how to track down UDP packet loss and related issues.

Now for the detailed information:

neubert wroteclient-config-dir /var/ipfire/ovpn/ccd

ccd file details

ifconfig-push XXX.XXX.38.38 XXX.XXX.38.37
push "route XXX.XXX.31.0 255.255.255.0"

neubert wroteserver XXX.XXX.39.0 255.255.255.0

is this a suitable address

Yes. Works in general. XXX.XXX.39.0/24 is the subnet from which openVPN clients get assigned dynamic IP addresses. openVPN clients with static IP addresses reside in the XXX.XXX.38.0/24 subnet.

neubert wrotetun-mtu 1400

do you need this

The maximum MTU as determined by

ping -M do -s 1464 SERVERFQDN

is 1492. So there is some headroom. I now turned forced path MTU discovery on at the home openVPN server and increased the MTU to the default 1500. Removed the tun-mtu setting on the client.

neubert wrotemax-clients 100

I presume your client is not number 101 ..

No, just a handful of clients.

neubert wrotetls-verify /usr/lib/openvpn/verify

does this work

Yes. Works in general.

neubert wrotecrl-verify /var/ipfire/ovpn/crls/cacrl.pem

is your client revoked

No. During the outage, it did not work with a newly issued client certificate and client configuration either.

neubert wroteverb 7

verb 4 is sufficient

Reduced it to 4 now on the server.

neubert wroteClient log:
Thu Mar 24 20:36:47 2016 us=944102 TLS Error: Unroutable control packet received from AF_INET]SERVERIP:1194 (si=3 op=P_ACK_V1)

I would say this is important.

One question, does your client have ethernet and wifi connections ?

No, only one ethernet interface (virtualized, it's a dynamic cloud server/virtual host rented from my ISP).

Kind regards
Boris

Traffic

neubert wroteThe VPN connection to home is restarted once in a while since then. The client log show:

Code:
Mar 25 10:42:43 s1 openvpn[11615]: TLS: tls_process: killed expiring key

every 30 minutes.

See --reneg-sec in The Manual v23x

neubert wroteverb 4 is sufficient

Reduced it to 4 now on the server.

Now would be a good time to post you new logs ..

neubert

Connection is running, but still intermittent failures:

Client log @17:21

Mar 26 15:50:34 s1 openvpn-bnuv[46750]: TLS: tls_process: killed expiring key
Mar 26 15:50:41 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 15:50:41 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 15:50:41 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 15:50:50 s1 openvpn-bnuv[46750]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Mar 26 16:50:41 s1 openvpn-bnuv[46750]: TLS: tls_process: killed expiring key
Mar 26 16:51:46 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:51:46 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 16:51:46 s1 openvpn-bnuv[46750]: TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
Mar 26 16:52:01 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=6ca58319 79879606
Mar 26 16:52:51 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 16:52:51 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 16:52:51 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 16:53:01 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:53:01 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 16:53:15 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=e25af8c9 101d8b62
Mar 26 16:54:01 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 16:54:01 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 16:54:01 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 16:54:15 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:54:15 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 16:54:32 s1 openvpn-bnuv[46750]: TLS Error: Unroutable control packet received from [AF_INET]SERVEREXTERNALIPADDRESS:1194 (si=3 op=P_ACK_V1)
Mar 26 16:54:36 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=309edfe5 b9b03bf0
Mar 26 16:55:22 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 16:55:22 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 16:55:22 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 16:55:30 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:55:30 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 16:55:44 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=ddf2b4a4 91403c36
Mar 26 16:56:42 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 16:56:42 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 16:56:42 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 16:56:44 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:56:44 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 16:56:59 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=73648a29 a0f57014
Mar 26 16:57:59 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:57:59 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 16:58:17 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=c018a536 e8e91eed
Mar 26 16:58:47 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 16:58:47 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 16:58:47 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 16:59:15 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:59:15 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 16:59:30 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=a4a67dae f78c0aa3
Mar 26 17:00:07 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 17:00:07 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 17:00:07 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 17:00:31 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:00:31 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 17:00:45 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=0196a308 5f70c498
Mar 26 17:01:23 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 17:01:23 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 17:01:23 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 17:01:45 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:01:45 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 17:02:00 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=341e6929 3187909d
Mar 26 17:02:51 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 17:02:51 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 17:02:51 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 17:03:00 s1 openvpn-bnuv[46750]: TLS: new session incoming connection from [AF_INET]SERVEREXTERNALIPADDRESS:1194
Mar 26 17:03:00 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:03:00 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 17:03:02 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=6de663e3 d13344c8
Mar 26 17:03:43 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 17:03:43 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 17:03:43 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 17:03:58 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 17:03:58 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 17:03:58 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 17:04:00 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:04:00 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 17:04:00 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:04:00 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 17:04:15 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=931da43f 9ac42b6a
Mar 26 17:05:10 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 17:05:10 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 17:05:10 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 17:05:15 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:05:15 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed
Mar 26 17:05:30 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=129fc232 68269113
Mar 26 17:05:52 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 17:05:52 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 17:05:52 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 17:05:58 s1 openvpn-bnuv[46750]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 17:05:58 s1 openvpn-bnuv[46750]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 17:05:58 s1 openvpn-bnuv[46750]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 17:05:58 s1 openvpn-bnuv[46750]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 17:06:01 s1 openvpn-bnuv[46750]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA

Server log:

Mar 26 16:50:41 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: tls_process: killed expiring key
Mar 26 16:50:44 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: soft reset sec=0 bytes=320583/0 pkts=1698/0
Mar 26 16:51:44 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:51:44 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 16:51:44 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
Mar 26 16:52:01 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=09b02c6b 4d2a774c
Mar 26 16:52:59 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:52:59 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 16:53:15 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=25b1b630 655d09a3
Mar 26 16:54:10 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY SCRIPT OK: depth=1, CERTIFICATEDETAILS1
Mar 26 16:54:10 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 CRL CHECK OK: CERTIFICATEDETAILS1
Mar 26 16:54:10 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY OK: depth=1, CERTIFICATEDETAILS1
Mar 26 16:54:10 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY SCRIPT OK: depth=0, CERTIFICATEDETAILS0
Mar 26 16:54:10 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 CRL CHECK OK: CERTIFICATEDETAILS0
Mar 26 16:54:10 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY OK: depth=0, CERTIFICATEDETAILS0
Mar 26 16:54:12 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 16:54:12 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 16:54:12 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 16:54:12 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 16:54:14 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:54:14 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 16:54:30 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=233b3720 d5c6757c
Mar 26 16:55:29 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:55:29 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 16:55:44 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=c743f65f 1492397c
Mar 26 16:56:44 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:56:44 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 16:56:59 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=b7263a1a bc0b61f5
Mar 26 16:57:59 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:57:59 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 16:58:15 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=20b9f236 4fa39a53
Mar 26 16:59:15 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:59:15 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 16:59:30 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=bf807f58 1adc53cc
Mar 26 17:00:30 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:00:30 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 17:00:45 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=480cc712 53f5af6c
Mar 26 17:01:45 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:01:45 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 17:02:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=af0cb21c 27a68c24
Mar 26 17:03:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:03:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 17:03:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: Unroutable control packet received from [AF_INET]CLIENTIPADDRESS:37032 (si=3 op=P_CONTROL_V1)
Mar 26 17:03:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=d20611f2 4053fb56
Mar 26 17:03:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: new session incoming connection from [AF_INET]CLIENTIPADDRESS:37032
Mar 26 17:04:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:04:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 17:04:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:04:00 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 17:04:15 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=a29c3b60 89cc4f98
Mar 26 17:05:15 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 17:05:15 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS Error: TLS handshake failed
Mar 26 17:05:30 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 TLS: Initial packet from [AF_INET]CLIENTIPADDRESS:37032, sid=ca701667 bfc8b2cb
Mar 26 17:05:56 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY SCRIPT OK: depth=1, CERTIFICATEDETAILS1
Mar 26 17:05:56 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 CRL CHECK OK: CERTIFICATEDETAILS1
Mar 26 17:05:56 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY OK: depth=1, CERTIFICATEDETAILS1
Mar 26 17:05:56 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY SCRIPT OK: depth=0, CERTIFICATEDETAILS0
Mar 26 17:05:56 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 CRL CHECK OK: CERTIFICATEDETAILS0
Mar 26 17:05:56 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 VERIFY OK: depth=0, CERTIFICATEDETAILS0
Mar 26 17:05:58 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 17:05:58 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 17:05:58 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 17:05:58 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 17:05:58 bunkertor openvpnserver[4768]: CLIENTFQDN/CLIENTIPADDRESS:37032 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA

Client config:

tls-client                                                                                                                                                                          
client                                                                                                                                                                              
nobind                                                                                                                                                                              
dev vpn-bnuv                                                                                                                                                                        
dev-type tun                                                                                                                                                                        
proto udp                                                                                                                                                                           
remote SERVERFQDN 1194                                                                                                                                                     
pkcs12 /etc/openvpn/bnuv.p12                                                                                                                                                        
cipher AES-256-CBC                                                                                                                                                                  
auth SHA1                                                                                                                                                                           
comp-lzo                                                                                                                                                                            
#verb 3                                                                                                                                                                             
verb 4

Server config:

daemon openvpnserver
writepid /var/run/openvpn.pid
;local SERVERFQDN
dev tun
proto udp
port 1194
script-security 3 system
ifconfig-pool-persist /var/ipfire/ovpn/ovpn-leases.db 3600
client-config-dir /var/ipfire/ovpn/ccd
tls-server
ca /var/ipfire/ovpn/ca/cacert.pem
cert /var/ipfire/ovpn/certs/servercert.pem
key /var/ipfire/ovpn/certs/serverkey.pem
dh /var/ipfire/ovpn/ca/dh1024.pem
server XXX.XXX.39.0 255.255.255.0
tun-mtu 1500
route XXX.XXX.38.0 255.255.255.0
mtu-disc yes
keepalive 10 60
status-version 1
status /var/run/ovpnserver.log 30
cipher AES-256-CBC
auth SHA1
comp-lzo
push "dhcp-option DNS XXX.XXX.31.1"
max-clients 100
tls-verify /usr/lib/openvpn/verify
crl-verify /var/ipfire/ovpn/crls/cacrl.pem
user nobody
group nobody
persist-key
persist-tun
verb 4

Traffic

Your logs do show some problems f.e

neubert wroteClient log @17:21

Code:
Mar 26 15:50:34 s1 openvpn-bnuv[46750]: TLS: tls_process: killed expiring key
Mar 26 15:50:41 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 15:50:41 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 15:50:41 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 26 15:50:44 s1 openvpn-bnuv[46750]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 26 15:50:50 s1 openvpn-bnuv[46750]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Mar 26 16:50:41 s1 openvpn-bnuv[46750]: TLS: tls_process: killed expiring key

Connected ok for an hour ..

neubert wroteMar 26 16:51:46 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 26 16:51:46 s1 openvpn-bnuv[46750]: TLS Error: TLS handshake failed

Then a failure ..

neubert wroteMar 26 16:51:46 s1 openvpn-bnuv[46750]: TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1

Interesting ..

neubert wroteMar 26 16:52:01 s1 openvpn-bnuv[46750]: TLS: Initial packet from [AF_INET]SERVEREXTERNALIPADDRESS:1194, sid=6ca58319 79879606
Mar 26 16:52:51 s1 openvpn-bnuv[46750]: VERIFY OK: depth=1, CERTIFCATEDETAILS1
Mar 26 16:52:51 s1 openvpn-bnuv[46750]: VERIFY OK: nsCertType=SERVER
Mar 26 16:52:51 s1 openvpn-bnuv[46750]: VERIFY OK: depth=0, CERTIFCATEDETAILS0
Mar 26 16:53:01 s1 openvpn-bnuv[46750]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

etc ..

I think you probably have a network problem ..

neubert wroteserver XXX.XXX.39.0 255.255.255.0

I presume this is an RFC1918 compliant subnet ?

What happens if you use a --proto tcp VPN ?

neubert

I changed the configuration for the home connection from udp to tcp while I left the office connection at udp.

I have been running this setup for a day so far. The tcp home connection is stable, i.e. no more errors about unroutable control packets and TLS handshake errors. At the same time, the udp office connection still has issues.

I this would like to conclude that the root cause of the problem are issues with the network connection that causes loss of udp packets. tcp connection works fine, though, due to the nature of tcp.

In the course of tracking down the problem I was also able to improve my configuration based on the hints I got.

I wish to thank you very much for your patience and guiding me through this. I marked this topic as solved.

Kind regards,
Boris

Traffic

So not solved ..

neubert

Well, not solved in the sense that the actual network connectivity problem that causes udp packet loss is not solved but worked around by using tcp. But solved from the openVPN angle, isn't it? Or is there anything else I can do to remedy the problem by means of the openVPN configuration?