OpenVPN broken since pfSense 2.1.1
-
I've tried pfSense 2.1.1, 2.1.2 and 2.1.3 but whenever I'm trying to copy data across the VPN tunnel the OpenVPN deamon dies with "event_wait : Interrupted system call (code=4)" error message. Its a site to site VPN with a pfSense 2.1 box at the other end.
When running pfSense 2.1 at both ends its rock stable.Maybe the pfSense team should start using two branches of updates, one with ONLY security fixes and one with both security and bug/improvement fixes a la how VMware does it.
Not being able to plug the serious security holes as of late due to other fixes/improvements that seems to have broken the OpenVPN functionality is not an optimal solution.
-
Was this clean install, upgrade? Are you am64 or i386? What hardware are you running on.
How is anyone suppose to help you find the source of your problem without any details? Maybe users should actually post information that can help them when they first post, because having to ask for it is not an optimal method ;)
-
Was this clean install, upgrade? Are you am64 or i386? What hardware are you running on.
How is anyone suppose to help you find the source of your problem without any details? Maybe users should actually post information that can help them when they first post, because having to ask for it is not an optimal method ;)
While I do agree with you completely about posting the required information (I really do ;) ), if I may add: it would be handy if the powers that be, together with the other powers that be (you know who you all are, fine forum members without whom etc 8) ) would compile and sticky a post with required information. I am an economist by education and profession, and I tried to at least tell something about my hardware in my sig. But for me, as a non-technical man, it is guessing what kind of information I would need to provide.
In my career I have worked for some huge companies (yes, Big Blue was one of them, I was over at ICG ;D ), and in there they had simple checklists for customers who required support: 'please provide us with the following information to speed up processing your ticket'.
I am sure the great powers & powers can easily make a list of CLI-outputs and such which will satisfy every need.
Just a thought from a stupid economist ;D
-
What other than the "Interrupted system call" is in your OpenVPN log at the time?
-
I've tried pfSense 2.1.1, 2.1.2 and 2.1.3 but whenever I'm trying to copy data across the VPN tunnel the OpenVPN deamon dies with "event_wait : Interrupted system call (code=4)" error message.
I'm having the same problem with OpenVPN client.
It will start and let a little data through, and repeat.
May 19 05:42:34 openvpn[13072]: event_wait : Interrupted system call (code=4)
May 19 05:42:34 openvpn[13072]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init
May 19 05:42:34 openvpn[13072]: SIGTERM[hard,] received, process exiting
May 19 05:42:34 openvpn[88542]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014
May 19 05:42:34 openvpn[88542]: NOTE: the current –script-security setting may allow this configuration to call user-defined scripts
May 19 05:42:34 openvpn[88542]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file
May 19 05:42:34 openvpn[88542]: TUN/TAP device ovpns1 exists previously, keep at program end
May 19 05:42:34 openvpn[88542]: TUN/TAP device /dev/tun1 opened
May 19 05:42:34 openvpn[88542]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
May 19 05:42:34 openvpn[88542]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up
May 19 05:42:34 openvpn[88542]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init
May 19 05:42:34 openvpn[90295]: UDPv4 link local (bound): [AF_INET][REDACTED]:1194
May 19 05:42:34 openvpn[90295]: UDPv4 link remote: [undef]
May 19 05:42:34 openvpn[90295]: Initialization Sequence Completed
May 19 05:42:56 openvpn[90295]: event_wait : Interrupted system call (code=4)
May 19 05:42:56 openvpn[90295]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init
May 19 05:42:56 openvpn[90295]: SIGTERM[hard,] received, process exiting
May 19 05:42:57 openvpn[3516]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014
May 19 05:42:57 openvpn[3516]: NOTE: the current –script-security setting may allow this configuration to call user-defined scripts
May 19 05:42:57 openvpn[3516]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file
May 19 05:42:57 openvpn[3516]: TUN/TAP device ovpns1 exists previously, keep at program end
May 19 05:42:57 openvpn[3516]: TUN/TAP device /dev/tun1 opened
May 19 05:42:57 openvpn[3516]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
May 19 05:42:57 openvpn[3516]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up
May 19 05:42:57 openvpn[3516]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init
May 19 05:42:57 openvpn[4565]: UDPv4 link local (bound): [AF_INET][REDACTED]:1194
May 19 05:42:57 openvpn[4565]: UDPv4 link remote: [undef]
May 19 05:42:57 openvpn[4565]: Initialization Sequence CompletedInterestingly, it only seems to happen when I am maxxing out my outbound bandwidth.
This is a graph of what it looks like on the bandwidth meter:
Any ideas on how to fix this?
-nb -
Just want to let you know that there is another thread on this problem:
-
Interestingly, it only seems to happen when I am maxxing out my outbound bandwidth.
Which will make your gateway latency and potentially loss go up, maybe enough to trigger a gateway failure from apinger, which is what I think is triggering it, check the gateways log.
-
@cmb:
Which will make your gateway latency and potentially loss go up, maybe enough to trigger a gateway failure from apinger, which is what I think is triggering it, check the gateways log.
OK, here's my Gateway log
May 20 04:40:04 apinger: ALARM: DSL1GW([REDACTED]) *** delay *** May 20 04:40:26 apinger: alarm canceled: DSL1GW([REDACTED]) *** delay *** May 20 04:41:46 apinger: ALARM: DSL1GW([REDACTED]) *** delay *** May 20 04:42:08 apinger: alarm canceled: DSL1GW([REDACTED]) *** delay *** May 20 04:43:33 apinger: ALARM: DSL1GW([REDACTED]) *** delay *** May 20 04:43:56 apinger: alarm canceled: DSL1GW([REDACTED]) *** delay *** May 20 05:28:51 apinger: ALARM: DSL1GW([REDACTED]) *** delay *** May 20 05:29:13 apinger: alarm canceled: DSL1GW([REDACTED]) *** delay *** May 20 05:31:16 apinger: ALARM: DSL1GW([REDACTED]) *** delay *** May 20 05:31:33 apinger: alarm canceled: DSL1GW([REDACTED]) *** delay ***
Here's my OpenVPN log for the same time frame.
May 20 04:40:16 openvpn[61945]: event_wait : Interrupted system call (code=4) May 20 04:40:16 openvpn[61945]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:40:16 openvpn[61945]: SIGTERM[hard,] received, process exiting May 20 04:40:16 openvpn[14124]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 04:40:16 openvpn[14124]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 04:40:16 openvpn[14124]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 04:40:16 openvpn[14124]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 04:40:16 openvpn[14124]: TUN/TAP device /dev/tun1 opened May 20 04:40:16 openvpn[14124]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 04:40:16 openvpn[14124]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 04:40:16 openvpn[14124]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:40:16 openvpn[15275]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 04:40:16 openvpn[15275]: UDPv4 link remote: [undef] May 20 04:40:16 openvpn[15275]: Initialization Sequence Completed May 20 04:40:38 openvpn[15275]: event_wait : Interrupted system call (code=4) May 20 04:40:38 openvpn[15275]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:40:38 openvpn[15275]: SIGTERM[hard,] received, process exiting May 20 04:40:39 openvpn[32312]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 04:40:39 openvpn[32312]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 04:40:39 openvpn[32312]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 04:40:39 openvpn[32312]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 04:40:39 openvpn[32312]: TUN/TAP device /dev/tun1 opened May 20 04:40:39 openvpn[32312]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 04:40:39 openvpn[32312]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 04:40:39 openvpn[32312]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:40:39 openvpn[33796]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 04:40:39 openvpn[33796]: UDPv4 link remote: [undef] May 20 04:40:39 openvpn[33796]: Initialization Sequence Completed May 20 04:41:20 openvpn: user 'VPN-User' authenticated May 20 04:41:20 openvpn[33796]: 216.40.154.16:60714 [VPN-User] Peer Connection Initiated with [AF_INET]216.40.154.16:60714 May 20 04:41:20 openvpn[33796]: VPN-User/216.40.154.16:60714 MULTI_sva: pool returned IPv4=192.168.129.6, IPv6=(Not enabled) May 20 04:41:22 openvpn[33796]: VPN-User/216.40.154.16:60714 send_push_reply(): safe_cap=940 May 20 04:41:58 openvpn[33796]: event_wait : Interrupted system call (code=4) May 20 04:41:58 openvpn[33796]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:41:58 openvpn[33796]: SIGTERM[hard,] received, process exiting May 20 04:41:58 openvpn[79735]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 04:41:58 openvpn[79735]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 04:41:58 openvpn[79735]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 04:41:58 openvpn[79735]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 04:41:58 openvpn[79735]: TUN/TAP device /dev/tun1 opened May 20 04:41:58 openvpn[79735]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 04:41:58 openvpn[79735]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 04:41:58 openvpn[79735]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:41:58 openvpn[80573]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 04:41:58 openvpn[80573]: UDPv4 link remote: [undef] May 20 04:41:58 openvpn[80573]: Initialization Sequence Completed May 20 04:42:20 openvpn[80573]: event_wait : Interrupted system call (code=4) May 20 04:42:20 openvpn[80573]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:42:20 openvpn[80573]: SIGTERM[hard,] received, process exiting May 20 04:42:21 openvpn[75584]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 04:42:21 openvpn[75584]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 04:42:21 openvpn[75584]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 04:42:21 openvpn[75584]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 04:42:21 openvpn[75584]: TUN/TAP device /dev/tun1 opened May 20 04:42:21 openvpn[75584]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 04:42:21 openvpn[75584]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 04:42:21 openvpn[75584]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:42:21 openvpn[77278]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 04:42:21 openvpn[77278]: UDPv4 link remote: [undef] May 20 04:42:21 openvpn[77278]: Initialization Sequence Completed May 20 04:43:03 openvpn: user 'VPN-User' authenticated May 20 04:43:03 openvpn[77278]: 216.40.154.16:60747 [VPN-User] Peer Connection Initiated with [AF_INET]216.40.154.16:60747 May 20 04:43:03 openvpn[77278]: VPN-User/216.40.154.16:60747 MULTI_sva: pool returned IPv4=192.168.129.6, IPv6=(Not enabled) May 20 04:43:05 openvpn[77278]: VPN-User/216.40.154.16:60747 send_push_reply(): safe_cap=940 May 20 04:43:46 openvpn[77278]: event_wait : Interrupted system call (code=4) May 20 04:43:46 openvpn[77278]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:43:46 openvpn[77278]: SIGTERM[hard,] received, process exiting May 20 04:43:46 openvpn[57199]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 04:43:46 openvpn[57199]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 04:43:46 openvpn[57199]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 04:43:46 openvpn[57199]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 04:43:46 openvpn[57199]: TUN/TAP device /dev/tun1 opened May 20 04:43:46 openvpn[57199]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 04:43:46 openvpn[57199]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 04:43:46 openvpn[57199]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:43:46 openvpn[58680]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 04:43:46 openvpn[58680]: UDPv4 link remote: [undef] May 20 04:43:46 openvpn[58680]: Initialization Sequence Completed May 20 04:44:08 openvpn[58680]: event_wait : Interrupted system call (code=4) May 20 04:44:08 openvpn[58680]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:44:08 openvpn[58680]: SIGTERM[hard,] received, process exiting May 20 04:44:09 openvpn[56809]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 04:44:09 openvpn[56809]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 04:44:09 openvpn[56809]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 04:44:09 openvpn[56809]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 04:44:09 openvpn[56809]: TUN/TAP device /dev/tun1 opened May 20 04:44:09 openvpn[56809]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 04:44:09 openvpn[56809]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 04:44:09 openvpn[56809]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 04:44:09 openvpn[58076]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 04:44:09 openvpn[58076]: UDPv4 link remote: [undef] May 20 04:44:09 openvpn[58076]: Initialization Sequence Completed May 20 04:44:50 openvpn: user 'VPN-User' authenticated May 20 04:44:50 openvpn[58076]: 216.40.154.16:60772 [VPN-User] Peer Connection Initiated with [AF_INET]216.40.154.16:60772 May 20 04:44:50 openvpn[58076]: VPN-User/216.40.154.16:60772 MULTI_sva: pool returned IPv4=192.168.129.6, IPv6=(Not enabled) May 20 04:44:52 openvpn[58076]: VPN-User/216.40.154.16:60772 send_push_reply(): safe_cap=940 May 20 05:29:04 openvpn[58076]: event_wait : Interrupted system call (code=4) May 20 05:29:04 openvpn[58076]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:29:04 openvpn[58076]: SIGTERM[hard,] received, process exiting May 20 05:29:04 openvpn[36837]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 05:29:04 openvpn[36837]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 05:29:04 openvpn[36837]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 05:29:04 openvpn[36837]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 05:29:04 openvpn[36837]: TUN/TAP device /dev/tun1 opened May 20 05:29:04 openvpn[36837]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 05:29:04 openvpn[36837]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 05:29:04 openvpn[36837]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:29:04 openvpn[37917]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 05:29:04 openvpn[37917]: UDPv4 link remote: [undef] May 20 05:29:04 openvpn[37917]: Initialization Sequence Completed May 20 05:29:25 openvpn[37917]: event_wait : Interrupted system call (code=4) May 20 05:29:25 openvpn[37917]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:29:25 openvpn[37917]: SIGTERM[hard,] received, process exiting May 20 05:29:25 openvpn[39238]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 05:29:25 openvpn[39238]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 05:29:25 openvpn[39238]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 05:29:25 openvpn[39238]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 05:29:25 openvpn[39238]: TUN/TAP device /dev/tun1 opened May 20 05:29:25 openvpn[39238]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 05:29:25 openvpn[39238]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 05:29:25 openvpn[39238]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:29:25 openvpn[39802]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 05:29:25 openvpn[39802]: UDPv4 link remote: [undef] May 20 05:29:25 openvpn[39802]: Initialization Sequence Completed May 20 05:30:08 openvpn: user 'VPN-User' authenticated May 20 05:30:08 openvpn[39802]: 216.40.154.16:61303 [VPN-User] Peer Connection Initiated with [AF_INET]216.40.154.16:61303 May 20 05:30:08 openvpn[39802]: VPN-User/216.40.154.16:61303 MULTI_sva: pool returned IPv4=192.168.129.6, IPv6=(Not enabled) May 20 05:30:10 openvpn[39802]: VPN-User/216.40.154.16:61303 send_push_reply(): safe_cap=940 May 20 05:31:28 openvpn[39802]: event_wait : Interrupted system call (code=4) May 20 05:31:28 openvpn[39802]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:31:28 openvpn[39802]: SIGTERM[hard,] received, process exiting May 20 05:31:28 openvpn[97105]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 05:31:28 openvpn[97105]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 05:31:28 openvpn[97105]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 05:31:28 openvpn[97105]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 05:31:28 openvpn[97105]: TUN/TAP device /dev/tun1 opened May 20 05:31:28 openvpn[97105]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 05:31:28 openvpn[97105]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 05:31:28 openvpn[97105]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:31:28 openvpn[98099]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 05:31:28 openvpn[98099]: UDPv4 link remote: [undef] May 20 05:31:28 openvpn[98099]: Initialization Sequence Completed May 20 05:31:45 openvpn[98099]: event_wait : Interrupted system call (code=4) May 20 05:31:45 openvpn[98099]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:31:45 openvpn[98099]: SIGTERM[hard,] received, process exiting May 20 05:31:45 openvpn[92376]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 05:31:45 openvpn[92376]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 05:31:45 openvpn[92376]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 05:31:45 openvpn[92376]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 05:31:45 openvpn[92376]: TUN/TAP device /dev/tun1 opened May 20 05:31:45 openvpn[92376]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 05:31:45 openvpn[92376]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 05:31:45 openvpn[92376]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 05:31:45 openvpn[93548]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 05:31:45 openvpn[93548]: UDPv4 link remote: [undef] May 20 05:31:45 openvpn[93548]: Initialization Sequence Completed
I can see what you are talking about. Hopefully this will bring us closer to a solution.
Thanks for your help!!!
-nb -
Have you tried adjusting the Gateway Latency Thresholds (System->Routing->Gateways(edit gateway)->Advanced) to try and stop the delays from getting triggered at all?
It might be worth a try at least for test purposes to set the Latency triggers up to 750 and 950 (ms) to eliminate any possibility of a trip. You might look at the RRD graphs around the time that you max out the VPN link to see what your max latency actually shows.
Historically I've run into similar problems, but always with very poor ADSL connections that show 500ms-850ms of latency :P
-
If you don't have any gateway alarms, there is a potential second cause I just fixed. Edit /etc/rc.newwanip and find where it has curnwanip in there. Replace that with curwanip (just remove the n), save, might want to reboot afterwards just to be 100% sure nothing is using the old code. Be careful when editing any code like that. That made things think your WAN IP had changed in cases where it hadn't, so it did things like restart VPNs where it was unnecessary.
-
Have you tried adjusting the Gateway Latency Thresholds (System->Routing->Gateways(edit gateway)->Advanced) to try and stop the delays from getting triggered at all?
It might be worth a try at least for test purposes to set the Latency triggers up to 750 and 950 (ms) to eliminate any possibility of a trip. You might look at the RRD graphs around the time that you max out the VPN link to see what your max latency actually shows.
Historically I've run into similar problems, but always with very poor ADSL connections that show 500ms-850ms of latency :P
Well, this seems to have fixed the problem. I set my ping threshold for this connection (which is only 768kbps upstream DSL) to 750/1000ms. My offsite backup is working again. I also haven't seen the OpenVPN message "event_wait : Interrupted system call (code=4)" since. And while it will spike up momentarily, it seems to have a nominal ping of around 300ms during this transfer. I'm running RDP simultaneously and it seems OK.
I'll have to check to see that the transfer runs through the night.
Thanks!!!
-nb
-
Great, we've reached step 1!
My suggestion would be to let it run a day or so (until you're happy it's OK), then try and break it again ;)
Actually, the previous post from cmb:
@cmb:
If you don't have any gateway alarms, there is a potential second cause I just fixed. Edit /etc/rc.newwanip and find where it has curnwanip in there. Replace that with curwanip (just remove the n), save, might want to reboot afterwards just to be 100% sure nothing is using the old code. Be careful when editing any code like that. That made things think your WAN IP had changed in cases where it hadn't, so it did things like restart VPNs where it was unnecessary.
Looks veeery much like the real culprit to your (and perhaps others' problems). That being said, I think it's important to keep your changes down to one at a time. So my suggestion is to leave it run with the "latency fix" for tonight/tomorrow (whatever you feel "proves" the fix) and then back the latency fix out (reset the values back to nothing/default).
Then apply the "rc.newwanip" fix and see if the problem stays away. If so I think that would be a great indication that you've isolated out an insidious little bug :-\
Perhaps cmb (or someone appropriate) could be talked into turning this into a patch?
Thanks for all the work on this guys :)
-
Last night's connections were definitely improved… but still not perfect.
Gateway log
May 20 23:56:37 apinger: ALARM: DSL1GW([REDACTED]) *** DSL1GWdelay *** May 20 23:56:52 apinger: alarm canceled: DSL1GW([REDACTED]) *** DSL1GWdelay *** May 20 23:58:19 apinger: alarm DSL1GW([REDACTED])canceled: WAN_DHCP([WAN-GW REDACTED]) *** WAN_DHCPdelay *** May 20 23:58:21 apinger: alarm DSL1GW([REDACTED])canceled: WAN_DHCP([WAN-GW REDACTED]) *** delay *** May 20 23:59:47 apinger: ALARM: DSL1GW([REDACTED]) *** DSL1GWdelay *** May 21 00:00:04 apinger: alarm canceled: DSL1GW([REDACTED]) *** DSL1GWdelay ***
OpenVPN log
May 20 22:54:19 openvpn[92487]: VPN-User/[REMOTE-VPN]:63582 send_push_reply(): safe_cap=940 May 20 23:54:23 openvpn: user 'VPN-User' authenticated May 20 23:56:49 openvpn[92487]: event_wait : Interrupted system call (code=4) May 20 23:56:49 openvpn[92487]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 23:56:49 openvpn[92487]: SIGTERM[hard,] received, process exiting May 20 23:56:49 openvpn[36824]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 23:56:49 openvpn[36824]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 23:56:49 openvpn[36824]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 23:56:49 openvpn[36824]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 23:56:49 openvpn[36824]: TUN/TAP device /dev/tun1 opened May 20 23:56:49 openvpn[36824]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 23:56:49 openvpn[36824]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 23:56:50 openvpn[36824]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 23:56:50 openvpn[38144]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 23:56:50 openvpn[38144]: UDPv4 link remote: [undef] May 20 23:56:50 openvpn[38144]: Initialization Sequence Completed May 20 23:57:04 openvpn[38144]: event_wait : Interrupted system call (code=4) May 20 23:57:04 openvpn[38144]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 23:57:04 openvpn[38144]: SIGTERM[hard,] received, process exiting May 20 23:57:05 openvpn[28211]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 20 23:57:05 openvpn[28211]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 20 23:57:05 openvpn[28211]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 20 23:57:05 openvpn[28211]: TUN/TAP device ovpns1 exists previously, keep at program end May 20 23:57:05 openvpn[28211]: TUN/TAP device /dev/tun1 opened May 20 23:57:05 openvpn[28211]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 20 23:57:05 openvpn[28211]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 20 23:57:05 openvpn[28211]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 23:57:05 openvpn[30193]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 20 23:57:05 openvpn[30193]: UDPv4 link remote: [undef] May 20 23:57:05 openvpn[30193]: Initialization Sequence Completed May 20 23:57:54 openvpn: user 'VPN-User' authenticated May 20 23:57:54 openvpn[30193]: [REMOTE-VPN]:50268 [VPN-User] Peer Connection Initiated with [AF_INET][REMOTE-VPN]:50268 May 20 23:57:54 openvpn[30193]: VPN-User/[REMOTE-VPN]:50268 MULTI_sva: pool returned IPv4=192.168.129.6, IPv6=(Not enabled) May 20 23:57:56 openvpn[30193]: VPN-User/[REMOTE-VPN]:50268 send_push_reply(): safe_cap=940 May 20 23:59:59 openvpn[30193]: event_wait : Interrupted system call (code=4) May 20 23:59:59 openvpn[30193]: /usr/local/sbin/ovpn-linkdown ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 20 23:59:59 openvpn[30193]: SIGTERM[hard,] received, process exiting May 21 00:00:00 openvpn[59943]: OpenVPN 2.3.2 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on Mar 27 2014 May 21 00:00:00 openvpn[59943]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts May 21 00:00:00 openvpn[59943]: Control Channel Authentication: using '/var/etc/openvpn/server1.tls-auth' as a OpenVPN static key file May 21 00:00:00 openvpn[59943]: TUN/TAP device ovpns1 exists previously, keep at program end May 21 00:00:00 openvpn[59943]: TUN/TAP device /dev/tun1 opened May 21 00:00:00 openvpn[59943]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0 May 21 00:00:00 openvpn[59943]: /sbin/ifconfig ovpns1 192.168.129.1 192.168.129.2 mtu 1500 netmask 255.255.255.255 up May 21 00:00:00 openvpn[59943]: /usr/local/sbin/ovpn-linkup ovpns1 1500 1558 192.168.129.1 192.168.129.2 init May 21 00:00:00 openvpn[61620]: UDPv4 link local (bound): [AF_INET][DSL1-IP]:1194 May 21 00:00:00 openvpn[61620]: UDPv4 link remote: [undef] May 21 00:00:00 openvpn[61620]: Initialization Sequence Completed
Since it is catching issues on the regular WAN as well, I think I need to apply the /etc/rc.newwanip fix and see what happens. I think my few problems were just internet latency issues (ISP, traffic, whatever)… but I'd like to try the other solution separately to see the result.
Thanks everyone for all your input and help.
-nb -
Hi,
I had similar issues. Adjusting the gateway monitoring issues seem to work for me as well.
Thanks,
Sean -
@cmb:
If you don't have any gateway alarms, there is a potential second cause I just fixed. Edit /etc/rc.newwanip and find where it has curnwanip in there. Replace that with curwanip (just remove the n), save, might want to reboot afterwards just to be 100% sure nothing is using the old code. Be careful when editing any code like that. That made things think your WAN IP had changed in cases where it hadn't, so it did things like restart VPNs where it was unnecessary.
Early indications (meaning: I applied this fix and rebooted, so exactly one data point) are that this fixed the EADDRINUSE bug that was causing my Openvpn (and that of others) to show up as "not running" in the gui even though it was (because somehow the pid in the pid file was wrong).
-
…what really is unpleasant is the time till the pfSense starts to use the new IP from DynDNS to re-establish the tunnel after a new IP has been given by the provider.
Right now, the new IP was at the DynDNS service at 21:49:18, but the box on the other side tried 6 times with the old IP to establish the tunnel and only at the 7th time (at 21:54:24, i.e. about 5 minutes after the update of the IP at the DynDNS) the tunnel came back...
-
@chemlud:
…what really is unpleasant is the time till the pfSense starts to use the new IP from DynDNS to re-establish the tunnel after a new IP has been given by the provider.
Right now, the new IP was at the DynDNS service at 21:49:18, but the box on the other side tried 6 times with the old IP to establish the tunnel and only at the 7th time (at 21:54:24, i.e. about 5 minutes after the update of the IP at the DynDNS) the tunnel came back...
OpenVPN will attempt reconnect once a minute, and will succeed as soon as its DNS lookup obtains the new IP. That's dependent on the TTL of your dyndns provider, and whether or not the DNS servers you're using obey the TTL to being with. OpenVPN will successfully reconnect within 1 minute at most of your DNS record's TTL expiring. From that, it sounds like you have a 5 minute TTL on your dyndns.
The best case scenario is the DNS TTL plus up to 1 minute. Cases where up to a ~2 minute outage in the case of an IP change server-side aren't acceptable shouldn't be using dynamic IPs on the server side (doesn't matter client-side). You can get it faster than 6 minutes for sure, but potentially up to 2 minutes is the best case scenario.
-
Many thanks for the detailed explanation, the TTL is crucial, I understand that fully… When I have a little time I will switch server and client for some tunnels... ;)
-
Update: Yesterday tunnels were stable for 24 hrs (since the last IP change on one tunnel end), no mysterious restarts of packages.
But 3 minutes after successful re-connect yesterday evening (change of IP on the other end of the tunnel), suddenly the Syslog has a
"check_reload_status: updating dyndns WAN_DHCP"
although the IP has NOT changed for this connection and the same second the box restarts IPsec/openVPN tunnels, reloads filters, restarts snort, the full program…
ADD: It was an apinger alarm delay, again…. :-\
Is it possible that there is an additional bug in the dyndns-updating script?
At another pfSense, where the IP does not change frequently I get a daily:
"php:rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days not passed. Not updating dynamic DNS entry"
in the Syslog.
![restart tunnels packages 22.05.2014.JPG](/public/imported_attachments/1/restart tunnels packages 22.05.2014.JPG)
![restart tunnels packages 22.05.2014.JPG_thumb](/public/imported_attachments/1/restart tunnels packages 22.05.2014.JPG_thumb) -
@cmb:
If you don't have any gateway alarms, there is a potential second cause I just fixed. Edit /etc/rc.newwanip and find where it has curnwanip in there. Replace that with curwanip (just remove the n), save, might want to reboot afterwards just to be 100% sure nothing is using the old code. Be careful when editing any code like that. That made things think your WAN IP had changed in cases where it hadn't, so it did things like restart VPNs where it was unnecessary.
I just tried reverting the latency settings for the gateway back to default and applying the change to /etc/rc/newwanip
Looks like that setting alone is not enough to fix the problem.
I'll add the latency settings back to the gateway.
-nb![DSL1 still choking.jpg](/public/imported_attachments/1/DSL1 still choking.jpg)
![DSL1 still choking.jpg_thumb](/public/imported_attachments/1/DSL1 still choking.jpg_thumb)