Bad VPN routing after internet reconnect?



  • Using pfsense 2.2.4 I route some of my inet traffic as openvpn client through proxy.sh . Basic OpenVPN client setup seems to work for hours but I am still fighting all sorts of long term reliability problems especialy with the 24h provider reconnect. Usualy openvpn on pfsense does not reconnect after the 24h reconnect of my inet provider.  Sometimes openvpn simply stays disconnected. But here is another case that happened and I need some expert help if my assumptions are correct:

    The openvpn config file /var/etc/openvpn/client1.conf generated/used by pfsense is:

    dev ovpnc1
    verb 1
    dev-type tun
    dev-node /dev/tun1
    writepid /var/run/openvpn_client1.pid
    #user nobody
    #group nobody
    script-security 3
    daemon
    keepalive 10 60
    ping-timer-rem
    persist-tun
    persist-key
    proto udp
    cipher AES-256-CBC
    auth SHA512
    up /usr/local/sbin/ovpn-linkup
    down /usr/local/sbin/ovpn-linkdown
    local 192.168.1.253
    tls-client
    client
    lport 0
    management /var/etc/openvpn/client1.sock unix
    remote de.proxy.sh 1194
    auth-user-pass /var/etc/openvpn/client1.up
    ca /var/etc/openvpn/client1.ca
    comp-lzo yes
    resolv-retry infinite
    route-nopull
    remote-cert-tls server
    

    Now the log below shows, how apinger correctly marks the gateway as down after the internet reconnection and also OpenVPN manages to reconnect and stay connected. But despite the running openvpn connection, there was no traffic possible through the vpn connection and the gateway thus did stay down.  Am I correct that this might be a problem of persist-tun always set by pfsense? After the openvpn reconnect proxy.sh did assign a different ip address to my openvpn client and there is a note in the log that seems pfsense is detecting the change, but it doesn't seem to work.  If I am correct, how do disable pfsense to set persist-tun? Regarding other suggestions: Disabling route-nopull doesn't seem to be an option as this messes up the internal routing of pfsense. Do I need to setup an additional route in pfsense? Currently I just use a gateway group for the VPN server and some basic firewall/nat rules for routing selected data through the vpn gateway group.

    Logfile:

    Sep  5 03:36:51 192.168.0.253 apinger: ALARM: GW_VPN_DE_HUB(8.8.8.8)  *** GW_VPN_DE_HUBdown ***
    Sep  5 03:37:01 192.168.0.253 check_reload_status: updating dyndns GW_VPN_DE_HUB
    Sep  5 03:37:01 192.168.0.253 check_reload_status: Restarting ipsec tunnels
    Sep  5 03:37:01 192.168.0.253 check_reload_status: Restarting OpenVPN tunnels/interfaces
    Sep  5 03:37:01 192.168.0.253 check_reload_status: Reloading filter
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.dyndns.update: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.dyndns.update: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.dyndns.update: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.dyndns.update: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_VPN_DE_HUB.
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_VPN_DE_HUB.
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.filter_configure_sync: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.filter_configure_sync: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.filter_configure_sync: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:02 192.168.0.253 php-fpm[54255]: /rc.filter_configure_sync: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:31 192.168.0.253 openvpn[77968]: [server] Inactivity timeout (--ping-restart), restarting
    Sep  5 03:37:31 192.168.0.253 openvpn[77968]: SIGUSR1[soft,ping-restart] received, process restarting
    Sep  5 03:37:33 192.168.0.253 openvpn[77968]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
    Sep  5 03:37:33 192.168.0.253 openvpn[77968]: UDPv4 link local (bound): [AF_INET]192.168.1.253
    Sep  5 03:37:33 192.168.0.253 openvpn[77968]: UDPv4 link remote: [AF_INET]178.63.194.204:1194
    Sep  5 03:37:34 192.168.0.253 openvpn[77968]: [server] Peer Connection Initiated with [AF_INET]178.63.194.204:1194
    Sep  5 03:37:39 192.168.0.253 openvpn[77968]: Options error: option 'redirect-gateway' cannot be used in this context ([PUSH-OPTIONS])
    Sep  5 03:37:39 192.168.0.253 openvpn[77968]: Options error: option 'dhcp-option' cannot be used in this context ([PUSH-OPTIONS])
    Sep  5 03:37:39 192.168.0.253 openvpn[77968]: Options error: option 'dhcp-option' cannot be used in this context ([PUSH-OPTIONS])
    Sep  5 03:37:39 192.168.0.253 openvpn[77968]: Options error: option 'route' cannot be used in this context ([PUSH-OPTIONS])
    Sep  5 03:37:39 192.168.0.253 openvpn[77968]: Preserving previous TUN/TAP instance: ovpnc1
    Sep  5 03:37:39 192.168.0.253 openvpn[77968]: NOTE: Pulled options changed on restart, will need to close and reopen TUN/TAP device.
    Sep  5 03:37:39 192.168.0.253 kernel: ovpnc1: link state changed to DOWN
    Sep  5 03:37:39 192.168.0.253 openvpn[77968]: /usr/local/sbin/ovpn-linkdown ovpnc1 1500 1602 10.10.0.10 10.10.0.9 init
    Sep  5 03:37:39 192.168.0.253 check_reload_status: Reloading filter
    Sep  5 03:37:40 192.168.0.253 openvpn[77968]: TUN/TAP device ovpnc1 exists previously, keep at program end
    Sep  5 03:37:40 192.168.0.253 kernel: ovpnc1: link state changed to UP
    Sep  5 03:37:40 192.168.0.253 openvpn[77968]: TUN/TAP device /dev/tun1 opened
    Sep  5 03:37:40 192.168.0.253 openvpn[77968]: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
    Sep  5 03:37:40 192.168.0.253 openvpn[77968]: /sbin/ifconfig ovpnc1 10.10.0.6 10.10.0.5 mtu 1500 netmask 255.255.255.255 up
    Sep  5 03:37:40 192.168.0.253 openvpn[77968]: /usr/local/sbin/ovpn-linkup ovpnc1 1500 1602 10.10.0.6 10.10.0.5 init
    Sep  5 03:37:40 192.168.0.253 check_reload_status: rc.newwanip starting ovpnc1
    Sep  5 03:37:40 192.168.0.253 openvpn[77968]: Initialization Sequence Completed
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.filter_configure_sync: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.filter_configure_sync: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.filter_configure_sync: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.filter_configure_sync: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: rc.newwanip: Info: starting on ovpnc1.
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: rc.newwanip: Info: starting on ovpnc1.
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: rc.newwanip: on (IP address: 10.10.0.6) (interface: VPN_DE_INTERFACE[opt3]) (real interface: ovpnc1).
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: rc.newwanip: on (IP address: 10.10.0.6) (interface: VPN_DE_INTERFACE[opt3]) (real interface: ovpnc1).
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: IP has changed, killing states on former IP 10.10.0.10.
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: IP has changed, killing states on former IP 10.10.0.10.
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:41 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:42 192.168.0.253 php-fpm[2119]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 10.10.0.5
    Sep  5 03:37:42 192.168.0.253 php-fpm[2119]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 10.10.0.5
    Sep  5 03:37:42 192.168.0.253 apinger: SIGHUP received, reloading configuration.
    Sep  5 03:37:42 192.168.0.253 apinger: alarm canceled (config reload): GW_VPN_DE_HUB(8.8.8.8)  *** GW_VPN_DE_HUBdown ***
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:43 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:44 192.168.0.253 dhcpd: Internet Systems Consortium DHCP Server 4.2.8
    Sep  5 03:37:44 192.168.0.253 dhcpd: Copyright 2004-2015 Internet Systems Consortium.
    Sep  5 03:37:44 192.168.0.253 dhcpd: All rights reserved.
    Sep  5 03:37:44 192.168.0.253 dhcpd: For info, please visit https://www.isc.org/software/dhcp/
    Sep  5 03:37:44 192.168.0.253 dhcpd: Internet Systems Consortium DHCP Server 4.2.8
    Sep  5 03:37:44 192.168.0.253 dhcpd: Copyright 2004-2015 Internet Systems Consortium.
    Sep  5 03:37:44 192.168.0.253 dhcpd: All rights reserved.
    Sep  5 03:37:44 192.168.0.253 dhcpd: For info, please visit https://www.isc.org/software/dhcp/
    Sep  5 03:37:44 192.168.0.253 dhcpd: Wrote 0 deleted host decls to leases file.
    Sep  5 03:37:44 192.168.0.253 dhcpd: Wrote 0 new dynamic host decls to leases file.
    Sep  5 03:37:44 192.168.0.253 dhcpd: Wrote 2 leases to leases file.
    Sep  5 03:37:44 192.168.0.253 dhcpd: Listening on BPF/bridge0/02:47:10:e5:ab:00/192.168.0.0/24
    Sep  5 03:37:44 192.168.0.253 dhcpd: Sending on   BPF/bridge0/02:47:10:e5:ab:00/192.168.0.0/24
    Sep  5 03:37:44 192.168.0.253 dhcpd: Sending on   Socket/fallback/fallback-net
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: Creating rrd update script
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: Creating rrd update script
    Sep  5 03:37:44 192.168.0.253 igmpproxy[16673]: select() failure; Errno(4): Interrupted system call
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: Started IGMP proxy service.
    Sep  5 03:37:44 192.168.0.253 php-fpm[2119]: /rc.newwanip: Started IGMP proxy service.
    Sep  5 03:37:46 192.168.0.253 php-fpm[2119]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.10.0.10 ->  10.10.0.6 - Restarting packages.
    Sep  5 03:37:46 192.168.0.253 php-fpm[2119]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.10.0.10 ->  10.10.0.6 - Restarting packages.
    Sep  5 03:37:46 192.168.0.253 check_reload_status: Starting packages
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: Restarting/Starting all packages.
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: Restarting/Starting all packages.
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 php-fpm[2119]: /rc.start_packages: sync_package_postfix called with via_rpc=no
    Sep  5 03:37:47 192.168.0.253 postfix/postfix-script[63059]: fatal: the Postfix mail system is already running
    Sep  5 03:38:02 192.168.0.253 apinger: ALARM: GW_VPN_DE_HUB(8.8.8.8)  *** GW_VPN_DE_HUBdown ***
    Sep  5 03:38:12 192.168.0.253 check_reload_status: updating dyndns GW_VPN_DE_HUB
    Sep  5 03:38:12 192.168.0.253 check_reload_status: Restarting ipsec tunnels
    Sep  5 03:38:12 192.168.0.253 check_reload_status: Restarting OpenVPN tunnels/interfaces
    Sep  5 03:38:12 192.168.0.253 check_reload_status: Reloading filter
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.dyndns.update: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.dyndns.update: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.dyndns.update: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.dyndns.update: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_VPN_DE_HUB.
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_VPN_DE_HUB.
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.filter_configure_sync: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.filter_configure_sync: MONITOR: GW_VPN_DE_HUB is down, omitting from routing group VPN_Group
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.filter_configure_sync: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    Sep  5 03:38:13 192.168.0.253 php-fpm[77116]: /rc.filter_configure_sync: Gateways status could not be determined, considering all as up/active. (Group: VPN_Group)
    
    

    My current idea to ugly fix the problems is to simply watch if apinger reports a gateway being down in /var/run/apinger.status use a simple bash script and than run echo "" | php -q to restart the openvpn client matching the gateway. Sounds ugly and takes longer than necessary to recover in some cases. Maybe someone here has already created some kind of "watchdog" to keep openvpn connections running 24h/7d.  Anybody with a better idea? Is is possible to get apinger start a script if a gateway gets down so that I can than handle the vpn reconnect?  But I really would also first like to even avoid runnning in this problem again by configuring things right.

    Being new to pfsense, I really wonder what pfsense users do to watch and keep the VPN links connected for months and not just some hours/days?