Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    OpenVPN UNDEF state

    2.1 Snapshot Feedback and Problems - RETIRED
    2
    6
    12.9k
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • P
      phil.davis
      last edited by

      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?

      As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
      If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

      1 Reply Last reply Reply Quote 0
      • jimpJ
        jimp Rebel Alliance Developer Netgate
        last edited by

        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.

        Remember: Upvote with the šŸ‘ button for any user/post you find to be helpful, informative, or deserving of recognition!

        Need help fast? Netgate Global Support!

        Do not Chat/PM for help!

        1 Reply Last reply Reply Quote 0
        • P
          phil.davis
          last edited by

          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.

          As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
          If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

          1 Reply Last reply Reply Quote 0
          • jimpJ
            jimp Rebel Alliance Developer Netgate
            last edited by

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

            How is the clock on both? Reasonably in sync?

            Remember: Upvote with the šŸ‘ button for any user/post you find to be helpful, informative, or deserving of recognition!

            Need help fast? Netgate Global Support!

            Do not Chat/PM for help!

            1 Reply Last reply Reply Quote 0
            • P
              phil.davis
              last edited by

              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.

              As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
              If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

              1 Reply Last reply Reply Quote 0
              • P
                phil.davis
                last edited by

                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ā€¦

                As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
                If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

                1 Reply Last reply Reply Quote 0
                • First post
                  Last post
                Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.