OpenVPN UNDEF state



  • 2.1-BETA1 (i386) built on Mon Mar 25 15:43:22 EDT 2013
    Alix 2D13 nanobsd

    OpenVPN server listening on OPT1 (same problem also if listening on a gateway group that contains just OPT1), OPT1 is a private subnet (10.49.81.1/24) to an ADSL router (10.49.81.250/24). The port is forwarded from the ADSL router public dynamic IP to pfSense OPT1. With client-specific overrides each client has a unique /30 tunnel network piece specified (so the tunnel pieces always get allocated the same - just for ease of fault-finding) and an iroute to the LAN at the client end. It all starts up fine. Note: WAN is default gateway, used for ordinary outgoing traffic - it is faster but can't be used for incoming stuff because the ISP has it behind a "sort of" carrier-grade NAT and I haven't found a way to trick it into running "backwards" yet.
    I get periods when my site-to-site OpenVPN server does not establish connections. The incoming connects from the clients are arriving OK, since I can see the following stuff in Status->OpenVPN (public IPs obfuscated):

    Site-to-Site Links UDP:4444 Client connections
    Common Name 	Real Address 	Virtual Address 	Connected Since 	Bytes Sent 	Bytes Received
    UNDEF 	202.79.11.111:36622 		Mon Apr 1 15:01:43 2013 	422 	210 	
    UNDEF 	49.244.201.11:10846 		Mon Apr 1 15:01:47 2013 	334 	168 	
    UNDEF 	49.244.202.22:11207 		Mon Apr 1 15:01:45 2013 	346 	210 	
    UNDEF 	49.244.203.33:28452 		Mon Apr 1 15:01:36 2013 	346 	210 	
    UNDEF 	49.244.204.44:17387 		Mon Apr 1 15:01:49 2013 	292 	168 	
    UNDEF 	202.79.22.222:11821 		Mon Apr 1 15:01:41 2013 	346 	210 	
    

    These disappear and then come again, as the client sites time out and try again.
    The OpenVPN log has just timeouts like this:

    Apr 1 15:08:54 	openvpn[72029]: 202.79.11.111:16911 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 1 15:08:54 	openvpn[72029]: 202.79.11.111:16911 TLS Error: TLS handshake failed
    Apr 1 15:08:56 	openvpn[72029]: 202.79.22.222:38649 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 1 15:08:56 	openvpn[72029]: 202.79.22.222:38649 TLS Error: TLS handshake failed
    Apr 1 15:08:59 	openvpn[72029]: 49.244.222.22:46795 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 1 15:08:59 	openvpn[72029]: 49.244.222.22:46795 TLS Error: TLS handshake failed
    Apr 1 15:09:00 	openvpn[72029]: 49.244.201.11:11534 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 1 15:09:00 	openvpn[72029]: 49.244.201.11:11534 TLS Error: TLS handshake failed
    Apr 1 15:09:02 	openvpn[72029]: 49.244.202.22:17437 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 1 15:09:02 	openvpn[72029]: 49.244.202.22:17437 TLS Error: TLS handshake failed
    

    The link setup protocol just never completes. Sometimes after an hour or so it all comes good. If I stop the OpenVPN server, wait 1 minute and start it again, then all the clients retry and connect (I think that if I do a restart - down and up straight away - it does not always fix the problem - but I need more samples). I don't touch the ADSL router to fix this, so the ADSL router port forwarding is OK. I don't reset any flow state tables to fix it. It can happen a couple of times a day - I suspect there is an ISP issue when it the problem first starts, then something in the link protocol negotiation seems to get into a knot and have trouble working itself out.
    Anyone else seen this? Any ideas for where to look next?


  • Rebel Alliance Developer Netgate

    Usually "undef" means the client state between making the initial network connection, and before the CERT/User/Pass have been verified.

    Check the client log as well as the server log, one of them should have more detail. I'd guess that for some reason they are rejecting the certificate from the server or vice versa.



  • Here is an interesting state. 1 of the clients shows UNDEF:

    Site-to-Site Links UDP:4444 Client connections
    Common Name 	Real Address 	Virtual Address 	Connected Since 	Bytes Sent 	Bytes Received
    INFN-IBP-to-IMP 	49.244.222.22:21810 	10.49.252.30 	Tue Apr 2 11:10:55 2013 	49104 	41760 	
    UNDEF 	49.244.234.56:29434 	10.49.252.26 	Tue Apr 2 11:11:06 2013 	323775 	354658 	
    INFN-IBP-to-KCHD 	49.244.223.33:10754 	10.49.252.38 	Tue Apr 2 11:10:42 2013 	84915 	88707 	
    

    It is now 12:20 - it has been like that for 1 hour 10 minutes. But I can traceroute to the client site:

    C:\Users\pdavis>tracert server.isp.infn
    
    Tracing route to server.isp.infn [10.49.104.1]
    over a maximum of 30 hops:
    
      1    <1 ms    <1 ms    <1 ms  pfsense.ibp.infn [10.49.80.250]
      2   319 ms     *      253 ms  10.49.252.26
      3   287 ms   356 ms   463 ms  server.isp.infn [10.49.104.1]
    
    Trace complete.
    

    It goes across the OpenVPN to 10.49.252.26 (the client OpenVPN end) then to the server.
    I can login to the pfSense GUI at the client end. The client staus is:

    Client Instance Statistics
    Name 	Status 	Connected Since 	Virtual Addr 	Remote Host 	Bytes Sent 	Bytes Received
    ISP to IBP UDP 	down 					
    ISP to ICO UDP 	up 	Tue Apr 2 8:10:33 2013 	10.49.251.26 	202.79.51.215 	320537 	345045 
    

    The IBP client says down, but clearly it is working.
    I can SSH to the client pfsense and see the client processes:

    [2.1-BETA1][admin@pfsense.isp.infn]/root(1): ps ax | grep openvpn
     1953  ??  RNs    0:09.79 /usr/local/sbin/openvpn --config /var/etc/openvpn/client2.conf
     7291  ??  SNs    0:03.24 /usr/local/sbin/openvpn --config /var/etc/openvpn/client1.conf
    11576   0  R+     0:00.00 grep openvpn
    
    

    There are 2 clients running, as expected.
    The client OpenVPN log has:

    Apr 2 11:11:03 	openvpn[1953]: [UNDEF] Inactivity timeout (--ping-restart), restarting
    Apr 2 11:11:03 	openvpn[1953]: SIGUSR1[soft,ping-restart] received, process restarting
    Apr 2 11:11:05 	openvpn[1953]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
    Apr 2 11:11:05 	openvpn[1953]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
    Apr 2 11:11:06 	openvpn[1953]: UDPv4 link local (bound): [AF_INET]10.49.105.1
    Apr 2 11:11:06 	openvpn[1953]: UDPv4 link remote: [AF_INET]49.244.178.139:4331
    Apr 2 11:11:41 	openvpn[1953]: [INFN-IBP-S2S-Server] Peer Connection Initiated with [AF_INET]49.244.178.139:4331
    Apr 2 11:11:44 	openvpn[1953]: TUN/TAP device ovpnc2 exists previously, keep at program end
    Apr 2 11:11:44 	openvpn[1953]: TUN/TAP device /dev/tun2 opened
    Apr 2 11:11:44 	openvpn[1953]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
    Apr 2 11:11:44 	openvpn[1953]: /sbin/ifconfig ovpnc2 10.49.252.26 10.49.252.25 mtu 1500 netmask 255.255.255.255 up
    Apr 2 11:11:44 	openvpn[1953]: /usr/local/sbin/ovpn-linkup ovpnc2 1500 1557 10.49.252.26 10.49.252.25 init
    Apr 2 11:11:45 	openvpn[1953]: ERROR: FreeBSD route add command failed: external program exited with error status: 1
    Apr 2 11:11:45 	openvpn[1953]: ERROR: FreeBSD route add command failed: external program exited with error status: 1
    Apr 2 11:11:45 	openvpn[1953]: Initialization Sequence Completed
    Apr 2 12:12:39 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:12:39 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:12:39 	openvpn[1953]: TLS ERROR: received control packet with stale session-id=963270a4 9a61983a
    Apr 2 12:12:39 	openvpn[1953]: TLS ERROR: received control packet with stale session-id=963270a4 9a61983a
    Apr 2 12:13:54 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:13:54 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:15:09 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:15:09 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:15:09 	openvpn[1953]: TLS Error: Unroutable control packet received from [AF_INET]49.244.178.139:4331 (si=3 op=P_ACK_V1)
    Apr 2 12:15:09 	openvpn[1953]: TLS Error: Unroutable control packet received from [AF_INET]49.244.178.139:4331 (si=3 op=P_ACK_V1)
    Apr 2 12:15:09 	openvpn[1953]: TLS Error: Unroutable control packet received from [AF_INET]49.244.178.139:4331 (si=3 op=P_ACK_V1)
    Apr 2 12:16:09 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:16:09 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:16:10 	openvpn[1953]: TLS Error: Unroutable control packet received from [AF_INET]49.244.178.139:4331 (si=3 op=P_ACK_V1)
    Apr 2 12:17:25 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:17:25 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:18:40 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:18:40 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:19:55 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:19:55 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:21:10 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:21:10 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:22:25 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:22:25 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:23:39 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:39 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:23:39 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:24:55 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:24:55 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:25:55 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:25:55 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:25:55 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:25:55 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:26:55 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:26:55 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:28:11 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:28:11 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:29:25 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:29:25 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:30:41 	openvpn[1953]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:30:41 	openvpn[1953]: TLS Error: TLS handshake failed
    Apr 2 12:31:47 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:48 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:48 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:49 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:49 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:50 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:52 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:54 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:55 	openvpn[1953]: Authenticate/Decrypt packet error: packet HMAC authentication failed
    

    So it did come up at 11:11, then from 12:12 it has been struggling, but hasn't dropped the link because I have been collecting all this log data over that link.
    Here is log from the server end:

    Apr 2 12:22:25 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:22:25 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:23:35 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:35 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:35 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:36 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:37 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:37 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:38 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:38 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:38 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:23:40 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:23:40 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:24:55 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:24:55 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:24:55 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: Unroutable control packet received from [AF_INET]49.244.224.71:29434 (si=3 op=P_CONTROL_V1)
    Apr 2 12:25:53 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: Unroutable control packet received from [AF_INET]49.244.224.71:29434 (si=3 op=P_ACK_V1)
    Apr 2 12:25:53 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: Unroutable control packet received from [AF_INET]49.244.224.71:29434 (si=3 op=P_ACK_V1)
    Apr 2 12:25:53 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: Unroutable control packet received from [AF_INET]49.244.224.71:29434 (si=3 op=P_ACK_V1)
    Apr 2 12:25:53 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: Unroutable control packet received from [AF_INET]49.244.224.71:29434 (si=3 op=P_ACK_V1)
    Apr 2 12:25:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:25:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:25:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:25:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:25:55 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:25:55 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:26:57 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:26:57 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:28:11 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:28:11 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:29:26 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:29:26 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:30:41 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
    Apr 2 12:30:41 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 TLS Error: TLS handshake failed
    Apr 2 12:31:48 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:49 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:49 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:50 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:50 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:51 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:51 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:52 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:53 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:53 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:31:55 	openvpn[24191]: INFN-IBP-to-ISP/49.244.224.71:29434 Authenticate/Decrypt packet error: packet HMAC authentication failed
    Apr 2 12:46:52 	openvpn[24191]: 49.244.222.45:25270 [INFN-IBP-to-ISP] Peer Connection Initiated with [AF_INET]49.244.222.45:25270
    Apr 2 12:46:54 	openvpn[24191]: INFN-IBP-to-ISP/49.244.222.45:25270 send_push_reply(): safe_cap=940
    

    The thing is struggling to get packets delivered error-free across the internet! The client gateway shows packet loss:

    WANGW 	10.49.105.250 	8.8.8.8 	967.7ms 	10% 
    

    Yes, it is a remote site in Nepal. Yes, they have a 512kbps link (good speed for here). Yes, the ISP has microwave towers on mountains. They seem to have difficulty with error rates. The packet loss comes and goes - nothing can be done about that until someone digs a trench and lays a fibre one day.
    As I type this, the server end is now reporting the correct client name (rather than UNDEF), but the client says the link is down, and I am using the client GUI.
    I have documented this one because it is interesting that pfSense GUI can report the OpenVPN link being down, but in fact the link is passing user traffic (admittedly from the log, the link is in a "struggling" state).
    When I again get the original situation of many clients struggling to connect and retrying every minute, I will check the server end link error rates etc. Perhaps it will turn out to be that the key exchange rarely completes successfully because of constant packet loss or corruption - can't blame OpenVPN or pfSense for that ;)
    PS: I got sick of editing out public IPs. We have Dynamic IPs that change, often the ISP resets things multiple times a day. So by the time some hacker tries these IPs they will be allocated to some other end-user anyway.


  • Rebel Alliance Developer Netgate

    What does the OpenVPN log show on the client side? It may have better detail.

    How is the clock on both? Reasonably in sync?



  • The client log is in the post above also - it has similar handshake/timeout/authentication failed etc messages. This one does look a lot like the packets are actually being corrupted and/or lost in transit.
    The clocks are fine just now - both sites within the same second matching to my laptop time from a visual, so the clock hasn't gone anywhere far away.
    In reality, modern-day internet protocols are not built to run at all smoothly with 10% packet loss and actual packet corruption. We expect that if a modern link/router delivers a packet then 99.9999999% of the time the packet content is accurate. A bit of packet loss due to congestion is accepted, as long as it is not a constant feature, and as long as the sender can back-off and the packet loss stops. With this remote location, both available ISPs have the same "features" in their service - due to the reality that the data ends up traversing the same microwave towers on the same hills.



  • 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…


Locked