OpenVPN timeout

[romain]

Hello there,

I have some strange behaviour with my openvpn. I have several timeouts and not related to my internet connection.

I have a low latency (6/10ms max) but sometime and without any explanations, I got ping with high latency 200/500 ms and few timeout. During these latency storm my internet is quite good (I still have 5/6 ms on different websites).

I tried to change tun vs tap and set the sndbuf and rcvbuf to 0 but nothing seems to be working.

The only thing I can do is to restart the service to be okay for few hours.

I changed the verobosity of the client and server log but I don't see anything.

Any idea on what's going on and what can I look into ?

Thank
Romain

[romain]

I've search a little bit more on my trouble and when all my users received a error message : Error: Inactivity timeout (--ping-restart), I can see that something is restarting the daemon openvpn server :

Jan  6 16:23:48 opnsense openvpn[54243]: event_wait : Interrupted system call (code=4)
Jan  6 16:23:48 opnsense openvpn[54243]: Closing TUN/TAP interface
Jan  6 16:23:48 opnsense openvpn[54243]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1602 172.31.129.1 255.255.255.224 init
Jan  6 16:23:51 opnsense openvpn[54243]: SIGTERM[hard,] received, process exiting
Jan  6 16:23:51 opnsense openvpn[41196]: OpenVPN 2.3.9 amd64-portbld-freebsd10.1 [SSL (OpenSSL)] [LZO] [MH] [IPv6] built on Dec 22 2015
Jan  6 16:23:51 opnsense openvpn[41196]: library versions: OpenSSL 1.0.2e 3 Dec 2015, LZO 2.09
Jan  6 16:23:51 opnsense openvpn[41763]: MANAGEMENT: unix domain socket listening on /var/etc/openvpn/server1.sock
Jan  6 16:23:51 opnsense openvpn[41763]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jan  6 16:23:51 opnsense openvpn[41763]: Diffie-Hellman initialized with 2048 bit key
Jan  6 16:23:51 opnsense openvpn[41763]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file
Jan  6 16:23:51 opnsense openvpn[41763]: Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Jan  6 16:23:51 opnsense openvpn[41763]: Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Jan  6 16:23:51 opnsense openvpn[41763]: Socket Buffers: R=[42080->42080] S=[57344->57344]
Jan  6 16:23:51 opnsense openvpn[41763]: TUN/TAP device ovpns1 exists previously, keep at program end
Jan  6 16:23:51 opnsense openvpn[41763]: TUN/TAP device /dev/tun1 opened
Jan  6 16:23:51 opnsense openvpn[41763]: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Jan  6 16:23:51 opnsense openvpn[41763]: /sbin/ifconfig ovpns1 172.31.129.1 172.31.129.2 mtu 1500 netmask 255.255.255.224 up
Jan  6 16:23:51 opnsense openvpn[41763]: /sbin/route add -net 172.31.129.0 172.31.129.1 255.255.255.224
Jan  6 16:23:51 opnsense openvpn[41763]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1602 172.31.129.1 255.255.255.224 init
Jan  6 16:23:52 opnsense openvpn[41763]: UDPv4 link local (bound): [AF_INET]80.80.236.212:1194
Jan  6 16:23:52 opnsense openvpn[41763]: UDPv4 link remote: [undef]
Jan  6 16:23:52 opnsense openvpn[41763]: MULTI: multi_init called, r=256 v=256
Jan  6 16:23:52 opnsense openvpn[41763]: IFCONFIG POOL: base=172.31.129.2 size=28, ipv6=0
Jan  6 16:23:52 opnsense openvpn[41763]: Initialization Sequence Completed
Jan  6 16:23:54 opnsense openvpn[55726]: event_wait : Interrupted system call (code=4)
Jan  6 16:23:54 opnsense openvpn[55726]: Closing TUN/TAP interface
Jan  6 16:23:54 opnsense openvpn[55726]: /usr/local/sbin/ovpn-linkdown ovpns2 1500 1601 172.31.130.1 255.255.255.192 init
Jan  6 16:23:57 opnsense openvpn[55726]: SIGTERM[hard,] received, process exiting
Jan  6 16:23:57 opnsense openvpn[39633]: OpenVPN 2.3.9 amd64-portbld-freebsd10.1 [SSL (OpenSSL)] [LZO] [MH] [IPv6] built on Dec 22 2015
Jan  6 16:23:57 opnsense openvpn[39633]: library versions: OpenSSL 1.0.2e 3 Dec 2015, LZO 2.09
Jan  6 16:23:57 opnsense openvpn[39904]: MANAGEMENT: unix domain socket listening on /var/etc/openvpn/server2.sock
Jan  6 16:23:57 opnsense openvpn[39904]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jan  6 16:23:57 opnsense openvpn[39904]: Diffie-Hellman initialized with 2048 bit key
Jan  6 16:23:57 opnsense openvpn[39904]: Control Channel Authentication: using '/var/etc/openvpn/server2.tls-auth' as a OpenVPN static key file
Jan  6 16:23:57 opnsense openvpn[39904]: Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Jan  6 16:23:57 opnsense openvpn[39904]: Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
Jan  6 16:23:57 opnsense openvpn[39904]: Socket Buffers: R=[42080->42080] S=[57344->57344]
Jan  6 16:23:57 opnsense openvpn[39904]: TUN/TAP device ovpns2 exists previously, keep at program end
Jan  6 16:23:57 opnsense openvpn[39904]: TUN/TAP device /dev/tun2 opened
Jan  6 16:23:57 opnsense openvpn[39904]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
Jan  6 16:23:57 opnsense openvpn[39904]: /sbin/ifconfig ovpns2 172.31.130.1 172.31.130.2 mtu 1500 netmask 255.255.255.192 up
Jan  6 16:23:57 opnsense openvpn[39904]: /sbin/route add -net 172.31.130.0 172.31.130.1 255.255.255.192
Jan  6 16:23:57 opnsense openvpn[39904]: /usr/local/sbin/ovpn-linkup ovpns2 1500 1601 172.31.130.1 255.255.255.192 init
Jan  6 16:23:57 opnsense openvpn[39904]: UDPv4 link local (bound): [AF_INET]80.80.236.212:1195
Jan  6 16:23:57 opnsense openvpn[39904]: UDPv4 link remote: [undef]
Jan  6 16:23:57 opnsense openvpn[39904]: MULTI: multi_init called, r=256 v=256
Jan  6 16:23:57 opnsense openvpn[39904]: IFCONFIG POOL: base=172.31.130.2 size=60, ipv6=0
Jan  6 16:23:57 opnsense openvpn[39904]: Initialization Sequence Completed

I have two OpenVPN (with different port and configuration) that receive a event_wait : Interrupted system call (code=4) which does a SIGTERM[hard,] received, process exiting

Do you have any idea of what's going on ? How can I debug from which process the restart daemon instruction come from ?

Thank you all !

[AdSchellevis]

Hi Romain,

It looks connection related, but you never know.
Is there more data before the "event_wait : Interrupted system call (code=4)" in the log? and what does the system.log report around that time frame?

Regards,

Ad

[romain]

If I look into the system.log. I have many things interesting. I didn't touch anything since few days now (even reload filter or updated GW_WAN).

Jan  7 04:24:40 opnsense kernel: pfr_update_stats: assertion failed.
Jan  7 04:38:09 opnsense configd.py: [124af91e-7b0b-4329-ab50-8552785e70b2] updating dyndns GW_WAN
Jan  7 04:38:09 opnsense configd.py: [0d6e9ea4-8c7a-4ef4-8e2b-9889308cc73c] Restarting ipsec tunnels
Jan  7 04:38:09 opnsense configd.py: [5382f117-bb23-4c84-8130-0e3985cf2cc0] Restarting OpenVPN tunnels/interfaces GW_WAN
Jan  7 04:38:10 opnsense opnsense: /usr/local/etc/rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_WA
N.
Jan  7 04:38:10 opnsense opnsense: /usr/local/etc/rc.openvpn: OpenVPN: Resync server1 VPN_SERVER_1
Jan  7 04:38:10 opnsense kernel: ovpns1: link state changed to DOWN
Jan  7 04:38:10 opnsense configd.py: [4cb63ed4-c503-482c-8199-2e7f235c12f1] Reloading filter
Jan  7 04:38:13 opnsense configd.py: [aea6d0f5-7e31-49bd-a057-fd5990db60ee] Reloading filter
Jan  7 04:38:13 opnsense kernel: ovpns1: link state changed to UP
Jan  7 04:38:13 opnsense configd.py: [b3cf52d3-5129-4f9e-aa0a-9a22572cb590] rc.newwanip starting ovpns1
Jan  7 04:38:13 opnsense opnsense: /usr/local/etc/rc.newwanip: rc.newwanip: Informational is starting ovpns1.
Jan  7 04:38:13 opnsense opnsense: /usr/local/etc/rc.newwanip: Interface is empty, nothing to do.
Jan  7 04:38:15 opnsense opnsense: /usr/local/etc/rc.openvpn: OpenVPN: Resync server2 VPN_SERVER_2
Jan  7 04:38:15 opnsense kernel: ovpns2: link state changed to DOWN
Jan  7 04:38:15 opnsense configd.py: [7225d8b9-1480-48f3-a8b5-6493c7d23b52] Reloading filter
Jan  7 04:38:18 opnsense configd.py: [81c492db-1b78-4a58-8cfd-7f5b261e2c38] Reloading filter
Jan  7 04:38:18 opnsense kernel: ovpns2: link state changed to UP
Jan  7 04:38:18 opnsense configd.py: [d513199b-0894-47cf-85f8-68171e1f51ae] rc.newwanip starting ovpns2
Jan  7 04:38:19 opnsense opnsense: /usr/local/etc/rc.newwanip: rc.newwanip: Informational is starting ovpns2.
Jan  7 04:38:19 opnsense opnsense: /usr/local/etc/rc.newwanip: Interface is empty, nothing to do.
Jan  7 04:38:21 opnsense configd.py: [50e82462-4b0a-4eee-934a-1a8767c0ec47] Reloading filter
Jan  7 04:39:07 opnsense configd.py: [d5347b54-5a47-4606-be60-8b1144f13a2b] updating dyndns GW_WAN
Jan  7 04:39:07 opnsense configd.py: [406cfcbe-13fa-4aa8-b908-d4130da5fa01] Restarting ipsec tunnels
Jan  7 04:39:08 opnsense configd.py: [5cb93580-f2e0-4ec8-82c7-5c5c7a8bc8a5] Restarting OpenVPN tunnels/interfaces GW_WAN
Jan  7 04:39:08 opnsense opnsense: /usr/local/etc/rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_WA
N.
Jan  7 04:39:08 opnsense opnsense: /usr/local/etc/rc.openvpn: OpenVPN: Resync server1 VPN_SERVER_1
Jan  7 04:39:08 opnsense kernel: ovpns1: link state changed to DOWN
Jan  7 04:39:08 opnsense configd.py: [d934784e-40c8-4932-b9f9-adf771b881c8] Reloading filter
Jan  7 04:39:11 opnsense configd.py: [65beb3f5-4027-434d-9d82-a7bd926a9369] Reloading filter
Jan  7 04:39:11 opnsense kernel: ovpns1: link state changed to UP
Jan  7 04:39:11 opnsense configd.py: [e56c8985-8585-4b38-9352-bd7db4ec0a07] rc.newwanip starting ovpns1
Jan  7 04:39:11 opnsense opnsense: /usr/local/etc/rc.newwanip: rc.newwanip: Informational is starting ovpns1.
Jan  7 04:39:11 opnsense opnsense: /usr/local/etc/rc.newwanip: Interface is empty, nothing to do.
Jan  7 04:39:14 opnsense opnsense: /usr/local/etc/rc.openvpn: OpenVPN: Resync server2 VPN_SERVER_2
Jan  7 04:39:14 opnsense kernel: ovpns2: link state changed to DOWN
Jan  7 04:39:14 opnsense configd.py: [e033c0f2-87ac-44b3-958c-d84e1efd54c2] Reloading filter
Jan  7 04:39:17 opnsense configd.py: [062d8244-fe8f-42ea-9e9a-5b6473a96ddc] Reloading filter
Jan  7 04:39:17 opnsense kernel: ovpns2: link state changed to UP
Jan  7 04:39:17 opnsense configd.py: [7c204faf-5113-485b-9b36-e126f982429c] rc.newwanip starting ovpns2
Jan  7 04:39:17 opnsense opnsense: /usr/local/etc/rc.newwanip: rc.newwanip: Informational is starting ovpns2.
Jan  7 04:39:17 opnsense opnsense: /usr/local/etc/rc.newwanip: Interface is empty, nothing to do.
Jan  7 04:39:19 opnsense configd.py: [9a7c1c44-076b-4144-80a3-c0a25d076650] Reloading filter

What do you think ?

[AdSchellevis]

This one:

Code: [Select]

Jan  7 04:24:40 opnsense kernel: pfr_update_stats: assertion failed.

seems to be causing the issue, it may be driver or hardware related. What kind of machine are you running OPNsense on and what's the temperature of the machine while suffering these issues?

Regards,

Ad

[romain]

Here my temperature sensor. Everything is green  :
http://imgur.com/I3dJYH4

It's a classic server super micro with Emulex OCE11102-NT additional network cards (10Gb/s) (http://www.supermicro.com/products/system/1U/5018/SYS-5018A-FTN4.cfm)

How can I know which hardware is causing the trouble ?

[AdSchellevis]

Not sure in this case, the biggest change is the network card, if you can manage with 1GBps for some time you could try to use the onboard ports to pinpoint your issue.
If that functions without issues, it can either be hardware or driver related. I'm not sure what driver is in FreeBSD 10.2 for your card, but if it's newer you could try the new kernel which will be in 16.1.

[romain]

It seems to be related to the monitoring of the gateway.

I changed to an IP closer (on the same network L2) and it works better.

However, if I do a download and take all the bandwith, the monitor see it and reload all the VPN tunnel (ipsec and openvpn)

Code: [Select]

updating dyndns GW_WAN
 Restarting ipsec tunnels
Restarting OpenVPN tunnels/interfaces GW_WAN
Do you know how I can avoid this ?