Reload every 30 secs



  • I got a reload loop again.
    While this loop RRD won't write quality data.

    It looks like TDSL had problems.
    Both openvpn server use a gateway group with WAN = Tier1 and TDSL = Tier5. WAN was always up.

    
    May 8 12:11:13 php: : Restarting/Starting all packages.
    May 8 12:11:11 php: : pfSense package system has detected an ip change 10.255.255.133 -> 10.255.255.133 ... Restarting packages.
    May 8 12:11:11 check_reload_status: Starting packages
    May 8 12:11:11 php: : pfSense package system has detected an ip change 10.255.255.129 -> 10.255.255.129 ... Restarting packages.
    May 8 12:11:09 php: : Creating rrd update script
    May 8 12:11:09 php: : Ignoring IPsec racoon daemon reload since there are no tunnels on interface opt8
    May 8 12:11:09 php: : Gateways status could not be determined, considering all as up/active. (Group: Internet)
    May 8 12:11:09 php: : Gateways status could not be determined, considering all as up/active. (Group: WAN)
    May 8 12:11:09 php: : Creating rrd update script
    May 8 12:11:09 php: : Ignoring IPsec racoon daemon reload since there are no tunnels on interface opt6
    May 8 12:11:09 php: : Gateways status could not be determined, considering all as up/active. (Group: Internet)
    May 8 12:11:09 php: : Gateways status could not be determined, considering all as up/active. (Group: WAN)
    May 8 12:11:08 php: : Removing static route for monitor 194.25.2.129 and adding a new route through 217.0.117.224
    May 8 12:11:08 php: : rc.newwanip: on (IP address: 10.255.255.133) (interface: opt8) (real interface: ovpns3).
    May 8 12:11:08 php: : rc.newwanip: Informational is starting ovpns3.
    May 8 12:11:08 php: : Removing static route for monitor 194.25.2.129 and adding a new route through 217.0.117.224
    May 8 12:11:08 php: : rc.newwanip: on (IP address: 10.255.255.129) (interface: opt6) (real interface: ovpns2).
    May 8 12:11:08 php: : rc.newwanip: Informational is starting ovpns2.
    May 8 12:11:06 check_reload_status: rc.newwanip starting ovpns3
    May 8 12:11:06 kernel: ovpns3: link state changed to UP
    May 8 12:11:06 php: : The command '/sbin/route -q delete 10.255.255.133' returned exit code '1', the output was 'route: writing to routing socket: No such process'
    May 8 12:11:06 kernel: ovpns3: link state changed to DOWN
    May 8 12:11:06 check_reload_status: rc.newwanip starting ovpns2
    May 8 12:11:06 kernel: ovpns2: link state changed to UP
    May 8 12:11:06 php: : The command '/sbin/route -q delete 10.255.255.129' returned exit code '1', the output was 'route: writing to routing socket: No such process'
    May 8 12:11:06 php: : Could not find IPv4 gateway for interface (opt6).
    May 8 12:11:05 kernel: ovpns2: link state changed to DOWN
    May 8 12:11:05 php: : IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    May 8 12:11:05 php: : OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_TDSL.
    May 8 12:11:03 check_reload_status: Reloading filter
    May 8 12:11:03 check_reload_status: Restarting OpenVPN tunnels/interfaces
    May 8 12:11:03 check_reload_status: Restarting ipsec tunnels
    May 8 12:11:03 check_reload_status: updating dyndns GW_TDSL
    
    


  • May 8 12:11:05 php: : OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_TDSL.

    This message is now logged to indicate that GW_TDSL has gone down or come up. If there are any OpenVPN instances (servers or clients) that were using, or should now be using GW_TDSL they will be restarted. For each OpenVPN instance that needs restarting, a message is logged like:

    OpenVPN: Resync client1 description
    

    Since there are no "OpenVPN: Resync" messages in your log, that means that the OpenVPN instances would have already been running on WAN, which remains the highest priority tier in the gateway group, so they do not need to be restarted when TDSL goes down or up. This is the expected behaviour now, avoiding interruption to OpenVPN services as much as possible.
    So I don't understand the "ovpns2" and "ovpns3" messages appearing.
    Can you give some more information about those server instances?
    How are they connected/related to GW_TDSL?
    (and of course there is the question of why GW_TDSL is going down and up a lot anyway!)



  • I did more research on this:

    TDSL use pppoe

    in PPP log this interface is up since 03:00 and didn't have any problem.

    while the reload loop TDSL had a big upstrem and the interface quality was >400ms.

    The are a lot of errors in this situation:

    openvpn didn't use this interface but was cyclic restarted, because it was in the gateway group

    "The command '/sbin/route -q delete 10.255.255.129' returned exit code '1', the output was 'route: writing to routing socket: No such process'"

    "pfSense package system has detected an ip change 10.255.255.129 -> 10.255.255.129 … Restarting packages"

    "Restarting/Starting all packages"

    RRD didn't record quality. I suppose apinger was restarted, too.

    TDSL come up again, because apinger was restarted.

    Here is the parallel log of openvpn:

    
    May 8 12:11:08 openvpn[76342]: Initialization Sequence Completed
    May 8 12:11:07 openvpn[76342]: Peer Connection Initiated with [AF_INET]62.159.224.202:32021
    May 8 12:11:07 openvpn[72914]: Initialization Sequence Completed
    May 8 12:11:06 openvpn[72914]: Peer Connection Initiated with [AF_INET]78.42.74.173:37562
    May 8 12:11:06 openvpn[76342]: UDPv4 link remote: [undef]
    May 8 12:11:06 openvpn[76342]: UDPv4 link local (bound): [AF_INET]213.188.120.106:1195
    May 8 12:11:06 openvpn[74834]: /usr/local/sbin/ovpn-linkup ovpns3 1500 1561 10.255.255.133 10.255.255.134 init
    May 8 12:11:06 openvpn[74834]: /sbin/ifconfig ovpns3 10.255.255.133 10.255.255.134 mtu 1500 netmask 255.255.255.255 up
    May 8 12:11:06 openvpn[74834]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
    May 8 12:11:06 openvpn[74834]: TUN/TAP device /dev/tun3 opened
    May 8 12:11:06 openvpn[74834]: TUN/TAP device ovpns3 exists previously, keep at program end
    May 8 12:11:06 openvpn[74834]: Initializing OpenSSL support for engine 'cryptodev'
    May 8 12:11:06 openvpn[74834]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
    May 8 12:11:06 openvpn[74834]: OpenVPN 2.3.1 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on May 6 2013
    May 8 12:11:06 openvpn[72413]: SIGTERM[hard,] received, process exiting
    May 8 12:11:06 openvpn[72413]: /usr/local/sbin/ovpn-linkdown ovpns3 1500 1561 10.255.255.133 10.255.255.134 init
    May 8 12:11:06 openvpn[72413]: event_wait : Interrupted system call (code=4)
    May 8 12:11:06 openvpn[72914]: UDPv4 link remote: [undef]
    May 8 12:11:06 openvpn[72914]: UDPv4 link local (bound): [AF_INET]213.188.120.106:1194
    May 8 12:11:06 openvpn[70929]: /usr/local/sbin/ovpn-linkup ovpns2 1500 1561 10.255.255.129 10.255.255.130 init
    May 8 12:11:06 openvpn[70929]: /sbin/ifconfig ovpns2 10.255.255.129 10.255.255.130 mtu 1500 netmask 255.255.255.255 up
    May 8 12:11:06 openvpn[70929]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
    May 8 12:11:06 openvpn[70929]: TUN/TAP device /dev/tun2 opened
    May 8 12:11:06 openvpn[70929]: TUN/TAP device ovpns2 exists previously, keep at program end
    May 8 12:11:06 openvpn[70929]: Initializing OpenSSL support for engine 'cryptodev'
    May 8 12:11:06 openvpn[70929]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
    May 8 12:11:06 openvpn[70929]: OpenVPN 2.3.1 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on May 6 2013
    May 8 12:11:05 openvpn[68978]: SIGTERM[hard,] received, process exiting
    May 8 12:11:05 openvpn[68978]: /usr/local/sbin/ovpn-linkdown ovpns2 1500 1561 10.255.255.129 10.255.255.130 init
    May 8 12:11:05 openvpn[68978]: event_wait : Interrupted system call (code=4)
    May 8 12:10:39 openvpn[68978]: Initialization Sequence Completed
    May 8 12:10:39 openvpn[72413]: Initialization Sequence Completed
    May 8 12:10:39 openvpn[72413]: Peer Connection Initiated with [AF_INET]62.159.224.202:32021
    May 8 12:10:38 openvpn[68978]: Peer Connection Initiated with [AF_INET]78.42.74.173:37562
    May 8 12:10:38 openvpn[72413]: UDPv4 link remote: [undef]
    May 8 12:10:38 openvpn[72413]: UDPv4 link local (bound): [AF_INET]213.188.120.106:1195
    May 8 12:10:38 openvpn[71295]: /usr/local/sbin/ovpn-linkup ovpns3 1500 1561 10.255.255.133 10.255.255.134 init
    May 8 12:10:38 openvpn[71295]: /sbin/ifconfig ovpns3 10.255.255.133 10.255.255.134 mtu 1500 netmask 255.255.255.255 up
    May 8 12:10:38 openvpn[71295]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
    May 8 12:10:38 openvpn[71295]: TUN/TAP device /dev/tun3 opened
    May 8 12:10:38 openvpn[71295]: TUN/TAP device ovpns3 exists previously, keep at program end
    May 8 12:10:38 openvpn[71295]: Initializing OpenSSL support for engine 'cryptodev'
    May 8 12:10:38 openvpn[71295]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
    May 8 12:10:38 openvpn[71295]: OpenVPN 2.3.1 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on May 6 2013
    May 8 12:10:38 openvpn[51955]: SIGTERM[hard,] received, process exiting
    May 8 12:10:38 openvpn[51955]: /usr/local/sbin/ovpn-linkdown ovpns3 1500 1561 10.255.255.133 10.255.255.134 init
    May 8 12:10:38 openvpn[51955]: event_wait : Interrupted system call (code=4)
    May 8 12:10:38 openvpn[68978]: UDPv4 link remote: [undef]
    May 8 12:10:38 openvpn[68978]: UDPv4 link local (bound): [AF_INET]213.188.120.106:1194
    May 8 12:10:38 openvpn[67832]: /usr/local/sbin/ovpn-linkup ovpns2 1500 1561 10.255.255.129 10.255.255.130 init
    May 8 12:10:38 openvpn[67832]: /sbin/ifconfig ovpns2 10.255.255.129 10.255.255.130 mtu 1500 netmask 255.255.255.255 up
    May 8 12:10:38 openvpn[67832]: do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
    May 8 12:10:38 openvpn[67832]: TUN/TAP device /dev/tun2 opened
    May 8 12:10:38 openvpn[67832]: TUN/TAP device ovpns2 exists previously, keep at program end
    May 8 12:10:38 openvpn[67832]: Initializing OpenSSL support for engine 'cryptodev'
    May 8 12:10:38 openvpn[67832]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
    May 8 12:10:38 openvpn[67832]: OpenVPN 2.3.1 amd64-portbld-freebsd8.3 [SSL (OpenSSL)] [LZO] [eurephia] [MH] [IPv6] built on May 6 2013
    May 8 12:10:37 openvpn[49000]: SIGTERM[hard,] received, process exiting
    May 8 12:10:37 openvpn[49000]: /usr/local/sbin/ovpn-linkdown ovpns2 1500 1561 10.255.255.129 10.255.255.130 init
    May 8 12:10:37 openvpn[49000]: event_wait : Interrupted system call (code=4)
    
    


  • "Could not find IPv4 gateway for interface (opt6)"

    opt6 has a dynamic gateway. Why comes this massage?

    opt8 has the same config. Why didn't come this massage for opt8, too?



  • TDSL use pppoe

    in PPP log this interface is up since 03:00 and didn't have any problem.

    while the reload loop TDSL had a big upstrem and the interface quality was >400ms.

    The default latency thresholds for apinger gateway monitoring are 200/500ms. When a WAN link is being saturated by upload and/or download then the ping latency is likely to go high, just because the ICMP packets get stuck in queues of traffic on the saturated link. Usually I don't want pfSense to declare the link down for stuff like this - the link is actually working at full capacity!
    I increase the latency thresholds in System->Routing Gateways, Edit Gateway, Advanced to something high - e.g. 1000 to 1500ms or even higher. That would probably prevent this apparent gateway flapping in your situation.


Log in to reply