The UNDEF state on the server happened again. All 6 clients were trying to connect again every minute, timing out and trying again…
Server log, some stuff comes up at 12:28, 12:36, then at 12:59 it gets timeouts. Then the TLS handshake failed messages loop around and around:
Apr 4 12:26:55 ibp-rt-01 openvpn[9966]: 49.244.218.198:14923 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 12:26:55 ibp-rt-01 openvpn[9966]: 49.244.218.198:14923 TLS Error: TLS handshake failed
Apr 4 12:26:57 ibp-rt-01 openvpn[9966]: INFN-IBP-to-ISP/49.244.223.237:13197 send_push_reply(): safe_cap=940
Apr 4 12:28:10 ibp-rt-01 openvpn[9966]: 49.244.218.198:15026 [INFN-IBP-to-IJP] Peer Connection Initiated with [AF_INET]49.244.218.198:15026
Apr 4 12:28:12 ibp-rt-01 openvpn[9966]: INFN-IBP-to-IJP/49.244.218.198:15026 send_push_reply(): safe_cap=940
Apr 4 12:36:21 ibp-rt-01 openvpn[9966]: 49.244.221.182:10166 [INFN-IBP-to-IDP] Peer Connection Initiated with [AF_INET]49.244.221.182:10166
Apr 4 12:36:23 ibp-rt-01 openvpn[9966]: INFN-IBP-to-IDP/49.244.221.182:10166 send_push_reply(): safe_cap=940
Apr 4 12:36:33 ibp-rt-01 openvpn[9966]: 49.244.221.182:10726 [INFN-IBP-to-IDP] Peer Connection Initiated with [AF_INET]49.244.221.182:10726
Apr 4 12:36:35 ibp-rt-01 openvpn[9966]: INFN-IBP-to-IDP/49.244.221.182:10726 send_push_reply(): safe_cap=940
Apr 4 12:59:08 ibp-rt-01 openvpn[9966]: INFN-IBP-to-ISP/49.244.223.237:13197 [INFN-IBP-to-ISP] Inactivity timeout (--ping-restart), restarting
Apr 4 12:59:09 ibp-rt-01 openvpn[9966]: INFN-IBP-to-IJP/49.244.218.198:15026 [INFN-IBP-to-IJP] Inactivity timeout (--ping-restart), restarting
Apr 4 12:59:09 ibp-rt-01 openvpn[9966]: INFN-IBP-to-KCHD/49.244.221.40:11695 [INFN-IBP-to-KCHD] Inactivity timeout (--ping-restart), restarting
Apr 4 12:59:11 ibp-rt-01 openvpn[9966]: INFN-IBP-to-IMP/49.244.252.110:14129 [INFN-IBP-to-IMP] Inactivity timeout (--ping-restart), restarting
Apr 4 12:59:12 ibp-rt-01 openvpn[9966]: INFN-IBP-to-IDP/49.244.246.190:13368 [INFN-IBP-to-IDP] Inactivity timeout (--ping-restart), restarting
Apr 4 13:01:15 ibp-rt-01 openvpn[9966]: 49.244.223.237:17763 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:01:15 ibp-rt-01 openvpn[9966]: 49.244.223.237:17763 TLS Error: TLS handshake failed
Apr 4 13:01:16 ibp-rt-01 openvpn[9966]: 49.244.218.198:19166 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:01:16 ibp-rt-01 openvpn[9966]: 49.244.218.198:19166 TLS Error: TLS handshake failed
Apr 4 13:01:17 ibp-rt-01 openvpn[9966]: 49.244.221.40:5806 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:01:17 ibp-rt-01 openvpn[9966]: 49.244.221.40:5806 TLS Error: TLS handshake failed
Apr 4 13:01:18 ibp-rt-01 openvpn[9966]: 49.244.246.190:15168 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:01:18 ibp-rt-01 openvpn[9966]: 49.244.246.190:15168 TLS Error: TLS handshake failed
Apr 4 13:01:18 ibp-rt-01 openvpn[9966]: 49.244.252.110:14251 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:01:18 ibp-rt-01 openvpn[9966]: 49.244.252.110:14251 TLS Error: TLS handshake failed
Apr 4 13:03:19 ibp-rt-01 openvpn[9966]: 49.244.223.237:17913 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:03:19 ibp-rt-01 openvpn[9966]: 49.244.223.237:17913 TLS Error: TLS handshake failed
Apr 4 13:03:20 ibp-rt-01 openvpn[9966]: 49.244.218.198:19511 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:03:20 ibp-rt-01 openvpn[9966]: 49.244.218.198:19511 TLS Error: TLS handshake failed
Apr 4 13:03:21 ibp-rt-01 openvpn[9966]: 49.244.246.190:15600 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:03:21 ibp-rt-01 openvpn[9966]: 49.244.246.190:15600 TLS Error: TLS handshake failed
Apr 4 13:03:22 ibp-rt-01 openvpn[9966]: 49.244.252.110:14259 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:03:22 ibp-rt-01 openvpn[9966]: 49.244.252.110:14259 TLS Error: TLS handshake failed
Apr 4 13:03:22 ibp-rt-01 openvpn[9966]: 49.244.221.40:53675 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:03:22 ibp-rt-01 openvpn[9966]: 49.244.221.40:53675 TLS Error: TLS handshake failed
...
One client log, client connected OK at 12:28, at 12:58 it lost connection and then loops around every minute trying to reconnect:
Apr 4 12:27:48 ijp-rt-01 openvpn[72206]: [UNDEF] Inactivity timeout (--ping-restart), restarting
Apr 4 12:27:48 ijp-rt-01 openvpn[72206]: SIGUSR1[soft,ping-restart] received, process restarting
Apr 4 12:27:50 ijp-rt-01 openvpn[72206]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Apr 4 12:27:50 ijp-rt-01 openvpn[72206]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 4 12:27:51 ijp-rt-01 openvpn[72206]: UDPv4 link local (bound): [AF_INET]10.49.121.1
Apr 4 12:27:51 ijp-rt-01 openvpn[72206]: UDPv4 link remote: [AF_INET]49.244.198.10:4331
Apr 4 12:28:10 ijp-rt-01 openvpn[72206]: [INFN-IBP-S2S-Server] Peer Connection Initiated with [AF_INET]49.244.198.10:4331
Apr 4 12:28:12 ijp-rt-01 openvpn[72206]: Preserving previous TUN/TAP instance: ovpnc3
Apr 4 12:28:12 ijp-rt-01 openvpn[72206]: Initialization Sequence Completed
Apr 4 12:58:09 ijp-rt-01 openvpn[72206]: [INFN-IBP-S2S-Server] Inactivity timeout (--ping-restart), restarting
Apr 4 12:58:09 ijp-rt-01 openvpn[72206]: SIGUSR1[soft,ping-restart] received, process restarting
Apr 4 12:58:11 ijp-rt-01 openvpn[72206]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Apr 4 12:58:11 ijp-rt-01 openvpn[72206]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 4 12:58:12 ijp-rt-01 openvpn[72206]: UDPv4 link local (bound): [AF_INET]10.49.121.1
Apr 4 12:58:12 ijp-rt-01 openvpn[72206]: UDPv4 link remote: [AF_INET]49.244.198.10:4331
Apr 4 12:59:12 ijp-rt-01 openvpn[72206]: [UNDEF] Inactivity timeout (--ping-restart), restarting
Apr 4 12:59:12 ijp-rt-01 openvpn[72206]: SIGUSR1[soft,ping-restart] received, process restarting
Apr 4 12:59:14 ijp-rt-01 openvpn[72206]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Apr 4 12:59:14 ijp-rt-01 openvpn[72206]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 4 12:59:14 ijp-rt-01 openvpn[72206]: UDPv4 link local (bound): [AF_INET]10.49.121.1
Apr 4 12:59:14 ijp-rt-01 openvpn[72206]: UDPv4 link remote: [AF_INET]49.244.213.116:4331
Apr 4 13:00:14 ijp-rt-01 openvpn[72206]: [UNDEF] Inactivity timeout (--ping-restart), restarting
Apr 4 13:00:14 ijp-rt-01 openvpn[72206]: SIGUSR1[soft,ping-restart] received, process restarting
Apr 4 13:00:16 ijp-rt-01 openvpn[72206]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Apr 4 13:00:16 ijp-rt-01 openvpn[72206]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 4 13:00:16 ijp-rt-01 openvpn[72206]: UDPv4 link local (bound): [AF_INET]10.49.121.1
Apr 4 13:00:16 ijp-rt-01 openvpn[72206]: UDPv4 link remote: [AF_INET]49.244.213.116:4331
Apr 4 13:01:16 ijp-rt-01 openvpn[72206]: [UNDEF] Inactivity timeout (--ping-restart), restarting
Apr 4 13:01:16 ijp-rt-01 openvpn[72206]: SIGUSR1[soft,ping-restart] received, process restarting
I stopped the server end for 15 seconds (13:12:19) and restarted it (13:12:34), it didn't recover. Then I stopped it for a couple of minutes (13:13:58) and restarted it (13:16:14), the links came back immediately the clients tried their next connect. The clients were not touched at all, they recovered themselves:
Apr 4 13:12:18 ibp-rt-01 openvpn[9966]: event_wait : Interrupted system call (code=4)
Apr 4 13:12:19 ibp-rt-01 openvpn[9966]: /usr/local/sbin/ovpn-linkdown ovpns7 1500 1557 10.49.252.1 10.49.252.2 init
Apr 4 13:12:19 ibp-rt-01 openvpn[9966]: SIGTERM[hard,] received, process exiting
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: OpenVPN 2.3.1 i386-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Apr 2 2013
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: Control Channel Authentication: using '/var/etc/openvpn/server7.tls-auth' as a OpenVPN static key file
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: TUN/TAP device ovpns7 exists previously, keep at program end
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: TUN/TAP device /dev/tun7 opened
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: /sbin/ifconfig ovpns7 10.49.252.1 10.49.252.2 mtu 1500 netmask 255.255.255.255 up
Apr 4 13:12:34 ibp-rt-01 openvpn[46782]: /usr/local/sbin/ovpn-linkup ovpns7 1500 1557 10.49.252.1 10.49.252.2 init
Apr 4 13:12:35 ibp-rt-01 openvpn[50311]: UDPv4 link local (bound): [AF_INET]10.49.81.1:4331
Apr 4 13:12:35 ibp-rt-01 openvpn[50311]: UDPv4 link remote: [undef]
Apr 4 13:12:35 ibp-rt-01 openvpn[50311]: Initialization Sequence Completed
Apr 4 13:13:42 ibp-rt-01 openvpn[50311]: 49.244.218.198:20393 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:13:42 ibp-rt-01 openvpn[50311]: 49.244.218.198:20393 TLS Error: TLS handshake failed
Apr 4 13:13:45 ibp-rt-01 openvpn[50311]: 202.79.37.158:18857 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:13:45 ibp-rt-01 openvpn[50311]: 202.79.37.158:18857 TLS Error: TLS handshake failed
Apr 4 13:13:45 ibp-rt-01 openvpn[50311]: 49.244.223.237:18965 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:13:45 ibp-rt-01 openvpn[50311]: 49.244.223.237:18965 TLS Error: TLS handshake failed
Apr 4 13:13:46 ibp-rt-01 openvpn[50311]: 49.244.252.110:14319 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:13:46 ibp-rt-01 openvpn[50311]: 49.244.252.110:14319 TLS Error: TLS handshake failed
Apr 4 13:13:47 ibp-rt-01 openvpn[50311]: 49.244.221.40:10287 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:13:47 ibp-rt-01 openvpn[50311]: 49.244.221.40:10287 TLS Error: TLS handshake failed
Apr 4 13:13:57 ibp-rt-01 openvpn[50311]: 49.244.210.208:13280 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Apr 4 13:13:57 ibp-rt-01 openvpn[50311]: 49.244.210.208:13280 TLS Error: TLS handshake failed
Apr 4 13:13:57 ibp-rt-01 openvpn[50311]: event_wait : Interrupted system call (code=4)
Apr 4 13:13:58 ibp-rt-01 openvpn[50311]: /usr/local/sbin/ovpn-linkdown ovpns7 1500 1557 10.49.252.1 10.49.252.2 init
Apr 4 13:13:58 ibp-rt-01 openvpn[50311]: SIGTERM[hard,] received, process exiting
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: OpenVPN 2.3.1 i386-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Apr 2 2013
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: Control Channel Authentication: using '/var/etc/openvpn/server7.tls-auth' as a OpenVPN static key file
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: TUN/TAP device ovpns7 exists previously, keep at program end
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: TUN/TAP device /dev/tun7 opened
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: /sbin/ifconfig ovpns7 10.49.252.1 10.49.252.2 mtu 1500 netmask 255.255.255.255 up
Apr 4 13:16:14 ibp-rt-01 openvpn[95284]: /usr/local/sbin/ovpn-linkup ovpns7 1500 1557 10.49.252.1 10.49.252.2 init
Apr 4 13:16:15 ibp-rt-01 openvpn[97681]: UDPv4 link local (bound): [AF_INET]10.49.81.1:4331
Apr 4 13:16:15 ibp-rt-01 openvpn[97681]: UDPv4 link remote: [undef]
Apr 4 13:16:15 ibp-rt-01 openvpn[97681]: Initialization Sequence Completed
Apr 4 13:17:09 ibp-rt-01 openvpn[97681]: 49.244.218.198:20523 [INFN-IBP-to-IJP] Peer Connection Initiated with [AF_INET]49.244.218.198:20523
Apr 4 13:17:13 ibp-rt-01 openvpn[97681]: INFN-IBP-to-IJP/49.244.218.198:20523 send_push_reply(): safe_cap=940
Apr 4 13:17:14 ibp-rt-01 openvpn[97681]: 202.79.37.158:21789 [INFN-IBP-to-NCO] Peer Connection Initiated with [AF_INET]202.79.37.158:21789
Apr 4 13:17:14 ibp-rt-01 openvpn[97681]: 49.244.221.40:54336 [INFN-IBP-to-KCHD] Peer Connection Initiated with [AF_INET]49.244.221.40:54336
Apr 4 13:17:16 ibp-rt-01 openvpn[97681]: INFN-IBP-to-KCHD/49.244.221.40:54336 send_push_reply(): safe_cap=940
Apr 4 13:17:16 ibp-rt-01 openvpn[97681]: INFN-IBP-to-NCO/202.79.37.158:21789 send_push_reply(): safe_cap=940
Apr 4 13:17:32 ibp-rt-01 openvpn[97681]: 49.244.252.110:14360 [INFN-IBP-to-IMP] Peer Connection Initiated with [AF_INET]49.244.252.110:14360
Apr 4 13:17:34 ibp-rt-01 openvpn[97681]: INFN-IBP-to-IMP/49.244.252.110:14360 send_push_reply(): safe_cap=940
Apr 4 13:17:35 ibp-rt-01 openvpn[97681]: 49.244.210.208:13783 [INFN-IBP-to-IDP] Peer Connection Initiated with [AF_INET]49.244.210.208:13783
Apr 4 13:17:37 ibp-rt-01 openvpn[97681]: 49.244.223.237:19125 [INFN-IBP-to-ISP] Peer Connection Initiated with [AF_INET]49.244.223.237:19125
Apr 4 13:17:39 ibp-rt-01 openvpn[97681]: INFN-IBP-to-IDP/49.244.210.208:13783 send_push_reply(): safe_cap=940
Apr 4 13:17:40 ibp-rt-01 openvpn[97681]: INFN-IBP-to-ISP/49.244.223.237:19125 send_push_reply(): safe_cap=940
Apr 4 13:30:40 ibp-rt-01 openvpn[97681]: 49.244.209.221:19823 [INFN-IBP-to-ISP] Peer Connection Initiated with [AF_INET]49.244.209.221:19823
Apr 4 13:30:42 ibp-rt-01 openvpn[97681]: INFN-IBP-to-ISP/49.244.209.221:19823 send_push_reply(): safe_cap=940
At the time of the first event, there was a change of external public IP address:
Apr 4 12:58:10 ibp-rt-01 php: : phpDynDNS: updating cache file /conf/dyndns_opt1dyndns'ntc-ibp-inf.dyndns-ip.com'0.cache: 49.244.213.116
Apr 4 12:58:10 ibp-rt-01 php: : phpDynDNS (ntc-ibp-inf.dyndns-ip.com): (Success) IP Address Changed Successfully! (49.244.213.116)
The public IP is on an ADSL router in front of the pfSense WAN. pfSense WAN has a static IP on a private subnet with the ADSL router. The ADSL router port forwards the OpenVPN server port to pfSense WAN.
As the client retries each minute, the source port from the client end changes each time, and is different from the source port that was used for the good connection that the server used to have. I guess the server needs to really give up on the previous client connection and be willing to start again from scratch?
Now to think about what needs to happen to make this recover automagically…