mojimbo
My setup:
A vpn server with 2 interfaces (linux machine):
1) eth0 using DHCP, connected via external router (which is also DHCP server) to outside world.
The IP address is almost static since the router is configured to deliver the same, reserved address to that MAC address.
So it doesn't change over time.
2) eth1 using static address for the internal LAN.
openvpn server only listens on internal eth1 above, keepalive values are 10 120, using UDP.
A vpn client machine (linux machine as well), single interface in the same subnet as 2) eth1 above.
Problem:
Connection establishment works well, connection is rather stable but ~every two hours the openvpn client complains about "Inactivity timeout (--ping-restart), restarting". Automatic restart works well but some client applications lose their connection.
This is a stable 1GB-connection. Nothing in the system logs reveal any problem.
My guess:
Every 2 hours the server's DHCP client renews its lease for eth0 (and always gets the same address).
Although the openvpn server doesn't listen on eth0 and although there is continious traffic via its TUN device it seems to forget about its keepalive pings (which AFAIK shouldn't be needed for an active connection with lots of traffic).
The openvpn client always expects the keepalive pings and restarts on the first missing ping.
Wouldn't this be several bugs?
mojimbo
After better examination of the logs (verb 4 on client side) there is a problem with TLS renegotiation.
=== server ===
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 TLS: soft reset sec=0 bytes=773216446/0 pkts=1113016/0
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 VERIFY OK: depth=1, ...
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 VERIFY OK: depth=0, ...
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 TLS Auth Error: TLS object CN=vpncli1 client-provided SSL certs unexpectedly changed during mid-session reauth
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 TLS Error: local/remote TLS keys are out of sync: [AF_INET]192.168.178.2:1194 [0]
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 TLS Error: local/remote TLS keys are out of sync: [AF_INET]192.168.178.2:1194 [0]
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
12:20:18+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 TLS Error: local/remote TLS keys are out of sync: [AF_INET]192.168.178.2:1194 [0]
12:20:34+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 SIGTERM[soft,auth-control-exit] received, client-instance exiting
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 TLS: Initial packet from [AF_INET]192.168.178.2:1194, sid=e89ab086 42806974
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 VERIFY OK: depth=1, ...
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 VERIFY OK: depth=0, ...
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
12:22:20+0900 vpnsrv openvpn[11689]: 192.168.178.2:1194 [vpncli1] Peer Connection Initiated with [AF_INET]192.168.178.2:1194
12:22:20+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 MULTI_sva: pool returned IPv4=10.9.0.8, IPv6=(Not enabled)
12:22:20+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 MULTI: Learn: 10.9.0.8 -> vpncli1/192.168.178.2:1194
12:22:20+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 MULTI: primary virtual IP for vpncli1/192.168.178.2:1194: 10.9.0.8
12:22:22+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 PUSH: Received control message: 'PUSH_REQUEST'
12:22:22+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 send_push_reply(): safe_cap=940
12:22:22+0900 vpnsrv openvpn[11689]: vpncli1/192.168.178.2:1194 SENT CONTROL [vpncli1]: 'PUSH_REPLY,route 10.9.0.0 255.255.255.0,topology net30,ifconfig 10.9.0.8 10.9.0.7' (status=1)
=== client ===
12:20:18+0900 vpncli1 openvpn[21652]: TLS: soft reset sec=0 bytes=773047418/0 pkts=1113016/0
12:20:18+0900 vpncli1 openvpn[21652]: VERIFY OK: depth=1, ...
12:20:18+0900 vpncli1 openvpn[21652]: VERIFY OK: nsCertType=SERVER
12:20:18+0900 vpncli1 openvpn[21652]: VERIFY OK: depth=0, ...
12:20:18+0900 vpncli1 openvpn[21652]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:20:18+0900 vpncli1 openvpn[21652]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:20:18+0900 vpncli1 openvpn[21652]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:20:18+0900 vpncli1 openvpn[21652]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:20:18+0900 vpncli1 openvpn[21652]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
12:22:18+0900 vpncli1 openvpn[21652]: [vpnsrv] Inactivity timeout (--ping-restart), restarting
12:22:18+0900 vpncli1 openvpn[21652]: TCP/UDP: Closing socket
12:22:18+0900 vpncli1 openvpn[21652]: SIGUSR1[soft,ping-restart] received, process restarting
12:22:18+0900 vpncli1 openvpn[21652]: Restart pause, 2 second(s)
12:22:20+0900 vpncli1 openvpn[21652]: Re-using SSL/TLS context
12:22:20+0900 vpncli1 openvpn[21652]: Control Channel MTU parms [ L:1541 D:138 EF:38 EB:0 ET:0 EL:0 ]
12:22:20+0900 vpncli1 openvpn[21652]: Socket Buffers: R=[212992->131072] S=[212992->131072]
12:22:20+0900 vpncli1 openvpn[21652]: Data Channel MTU parms [ L:1541 D:1450 EF:41 EB:4 ET:0 EL:0 ]
12:22:20+0900 vpncli1 openvpn[21652]: Local Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
12:22:20+0900 vpncli1 openvpn[21652]: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
12:22:20+0900 vpncli1 openvpn[21652]: Local Options hash (VER=V4): '7881c159'
12:22:20+0900 vpncli1 openvpn[21652]: Expected Remote Options hash (VER=V4): 'a5fa4c96'
12:22:20+0900 vpncli1 openvpn[21652]: UDPv4 link local (bound): [undef]
12:22:20+0900 vpncli1 openvpn[21652]: UDPv4 link remote: [AF_INET]192.168.178.42:1194
12:22:20+0900 vpncli1 openvpn[21652]: TLS: Initial packet from [AF_INET]192.168.178.42:1194, sid=bb5d7e1e 3559436f
12:22:20+0900 vpncli1 openvpn[21652]: VERIFY OK: depth=1, ...
12:22:20+0900 vpncli1 openvpn[21652]: VERIFY OK: nsCertType=SERVER
12:22:20+0900 vpncli1 openvpn[21652]: VERIFY OK: depth=0, ...
12:22:20+0900 vpncli1 openvpn[21652]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:22:20+0900 vpncli1 openvpn[21652]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:22:20+0900 vpncli1 openvpn[21652]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:22:20+0900 vpncli1 openvpn[21652]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:22:20+0900 vpncli1 openvpn[21652]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
12:22:20+0900 vpncli1 openvpn[21652]: [vpnsrv] Peer Connection Initiated with [AF_INET]192.168.178.42:1194
12:22:22+0900 vpncli1 openvpn[21652]: SENT CONTROL [vpnsrv]: 'PUSH_REQUEST' (status=1)
12:22:22+0900 vpncli1 openvpn[21652]: PUSH: Received control message: 'PUSH_REPLY,route 10.9.0.0 255.255.255.0,topology net30,ifconfig 10.9.0.8 10.9.0.7'
Who fails, the server or the client side? More important: What can I do to fix it?
From the logs it is always the client who initiates renegotiation, which sometimes succeeds.
So there are one-hour and two-hour intervals until the client restarts.
Does the client use the new certs too early while renegotiation is not yet completed?
