pfSense 2.6.0 Fails to Recover after WAN Issues
-
Thanks @michmoor and @stephenw10 for the reply.
At the moment all is well and things are working normally, but I was wondering if there is any forensic work that I can do, or any other things I should try if/when the problem reoccurs.
My internet connection is generally very reliable, but every 2 or 3 months, things go flaky - either the modem goes down, something upstream goes down for a period of time and pfSense doesn't recover properly once connectivity is restored. My goal is to find out if this is due to a pfSense bug (in which case I can contribute something to the devs to help them improve the system), or if I have a configuration error that I need to fix. I would like to avoid having to manually intervene and reset pfSense if possible.
In this latest incident, the two obvious symptoms were:
-
Both the LAN and OpenVPN showed as offline (dpinger not providing the correct answer for WAN). The WAN appeared to be operating normally, since Non-VPN traffic was normal for systems not routed to the VPN, and I was able to ping from the shell.
VPN traffic was blocked, so OpenVPN connectivity was correctly shown as down. -
The OpenVPN service was shown as running in the OpenVPN GUI, but could not be stopped or restarted.
In the past I believe unbound was involved, but I'm not sure if that was the case in the latest incidents.
It is also possible that it has something to do with IPv6, which I have disabled on all interfaces since I don't have the knowledge at this point to deal with the security/privacy risks. Is it possible that some local IPv6 connectivity required to reestablish a connection after an outage? (Everything works fine when I reboot pfSense (Note that I did not/and did not need to reboot the cable modem to get things working again.)
@michmoor said in pfSense 2.6.0 Fails to Recover after WAN Issues:
@guardian your monitor IP was not replying to pings.
Actually that was not the problem because that address did respond to pings issued through the shell. Either there was some sort of network stack error blocking communication betwen dpinger and the outside world, or dpinger had stopped pinging for some reason. Next time I'll do what @stephenw10 suggested.
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
Check the monitoring pings are actually leaving the WAN still when it fails. A pcap there will confirm it.
Good idea, I should have thought of this and tried it out. I don't know if something caused dpinger to stop pinging.
Anything else to do here, or do I just wait till the next time?
(I did save a complete copy of /var/log just in case there was something useful) -
-
You might also check the state table for the monitoring pings. Make sure the outbound states are present and on the correct interfaces.
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
You might also check the state table for the monitoring pings. Make sure the outbound states are present and on the correct interfaces.
I had another incident, and this time when I had a look at the log, it was pretty obvious that dpinger died. I don't know if this log info provides any clues, but it's clear there are a few things that look off. I restarted the DNS resolver which restored traffic, but dpinger didn't restart, so I rebooted the system.
Feb 7 03:13:12 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:13:12 pfsense kernel: em0: link state changed to DOWN Feb 7 03:13:13 pfsense php-fpm[358]: /rc.linkup: DEVD Ethernet detached event for wan Feb 7 03:13:14 pfsense php-fpm[358]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.13.110.16 Feb 7 03:13:14 pfsense check_reload_status[396]: Reloading filter Feb 7 03:13:15 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:13:15 pfsense kernel: em0: link state changed to UP Feb 7 03:13:16 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:13:16 pfsense kernel: em0: link state changed to DOWN Feb 7 03:13:16 pfsense php-fpm[44538]: /rc.linkup: DEVD Ethernet attached event for wan Feb 7 03:13:16 pfsense php-fpm[44538]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 7 03:13:16 pfsense rc.gateway_alarm[75684]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 7 03:13:16 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 7 03:13:16 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 7 03:13:16 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 7 03:13:16 pfsense check_reload_status[396]: Reloading filter Feb 7 03:13:17 pfsense php-fpm[45779]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 7 03:13:17 pfsense php-fpm[45779]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 7 03:13:19 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:13:19 pfsense kernel: em0: link state changed to UP Feb 7 03:14:16 pfsense kernel: ovpnc1: link state changed to DOWN Feb 7 03:14:16 pfsense check_reload_status[396]: Reloading filter Feb 7 03:14:22 pfsense kernel: em0: link state changed to DOWN Feb 7 03:14:22 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:14:24 pfsense kernel: em0: link state changed to UP Feb 7 03:14:24 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:14:25 pfsense kernel: em0: link state changed to DOWN Feb 7 03:14:25 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:14:29 pfsense kernel: em0: link state changed to UP Feb 7 03:14:29 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:15:00 pfsense php[12557]: [pfBlockerNG] Starting cron process. Feb 7 03:15:00 pfsense root[19879]: ***** 23/02/07-03:15:00-WAN is down-VPN restart not attempted. Feb 7 03:15:32 pfsense kernel: em0: link state changed to DOWN Feb 7 03:15:32 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:15:38 pfsense kernel: em0: link state changed to UP Feb 7 03:15:38 pfsense check_reload_status[396]: Linkup starting em0 Feb 7 03:16:00 pfsense root[81162]: ~~~~~ 23/02/07-03:16:00-WAN is down-DNS restart not attempted. Feb 7 03:16:59 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:16:59 pfsense php-fpm[44538]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 7 03:16:59 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 7 03:17:06 pfsense php-fpm[44538]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:17:06 pfsense check_reload_status[396]: updating dyndns wan Feb 7 03:17:40 pfsense php-fpm[44538]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1675757860] unbound[35458:0] error: bind: address already in use [1675757860] unbound[35458:0] fatal error: could not open ports' Feb 7 03:17:41 pfsense php-fpm[44538]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:17:41 pfsense check_reload_status[396]: Reloading filter Feb 7 03:17:41 pfsense php-fpm[43269]: /rc.linkup: DEVD Ethernet detached event for wan Feb 7 03:17:42 pfsense check_reload_status[396]: Reloading filter Feb 7 03:17:42 pfsense php-fpm[358]: /rc.linkup: DEVD Ethernet attached event for wan Feb 7 03:17:42 pfsense php-fpm[358]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 7 03:17:42 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:17:42 pfsense php-fpm[358]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 7 03:17:42 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 7 03:17:47 pfsense php-fpm[358]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:17:47 pfsense check_reload_status[396]: updating dyndns wan Feb 7 03:17:47 pfsense php-fpm[44538]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:17:47 pfsense php-fpm[44538]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:17:47 pfsense check_reload_status[396]: Reloading filter Feb 7 03:18:01 pfsense php-fpm[44538]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:18:01 pfsense php-fpm[44538]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:18:01 pfsense check_reload_status[396]: Reloading filter Feb 7 03:18:22 pfsense php-fpm[358]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1675757902] unbound[63326:0] error: bind: address already in use [1675757902] unbound[63326:0] fatal error: could not open ports' Feb 7 03:18:23 pfsense php-fpm[358]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:18:23 pfsense check_reload_status[396]: Reloading filter Feb 7 03:18:23 pfsense php-fpm[40797]: /rc.linkup: DEVD Ethernet detached event for wan Feb 7 03:18:24 pfsense check_reload_status[396]: Reloading filter Feb 7 03:18:24 pfsense php-fpm[359]: /rc.linkup: DEVD Ethernet attached event for wan Feb 7 03:18:24 pfsense php-fpm[359]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 7 03:18:24 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:18:24 pfsense php-fpm[359]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 7 03:18:24 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 7 03:18:25 pfsense php-fpm[358]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:18:25 pfsense php-fpm[358]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:18:25 pfsense check_reload_status[396]: Reloading filter Feb 7 03:18:29 pfsense php-fpm[359]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:18:30 pfsense check_reload_status[396]: updating dyndns wan Feb 7 03:19:04 pfsense php-fpm[359]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1675757944] unbound[15210:0] error: bind: address already in use [1675757944] unbound[15210:0] fatal error: could not open ports' Feb 7 03:19:05 pfsense php-fpm[359]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:19:05 pfsense check_reload_status[396]: Reloading filter Feb 7 03:19:05 pfsense php-fpm[43774]: /rc.linkup: DEVD Ethernet detached event for wan Feb 7 03:19:06 pfsense check_reload_status[396]: Reloading filter Feb 7 03:19:06 pfsense php-fpm[59923]: /rc.linkup: DEVD Ethernet attached event for wan Feb 7 03:19:06 pfsense php-fpm[59923]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 7 03:19:06 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:19:06 pfsense php-fpm[59923]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 7 03:19:06 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 7 03:19:07 pfsense php-fpm[358]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:19:07 pfsense php-fpm[358]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:19:07 pfsense check_reload_status[396]: Reloading filter Feb 7 03:19:11 pfsense php-fpm[59923]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:19:12 pfsense check_reload_status[396]: updating dyndns wan Feb 7 03:19:46 pfsense php-fpm[59923]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1675757986] unbound[95841:0] error: bind: address already in use [1675757986] unbound[95841:0] fatal error: could not open ports' Feb 7 03:19:47 pfsense php-fpm[59923]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:19:47 pfsense check_reload_status[396]: Reloading filter Feb 7 03:19:47 pfsense php-fpm[45779]: /rc.linkup: DEVD Ethernet detached event for wan Feb 7 03:19:49 pfsense php-fpm[43269]: /rc.linkup: DEVD Ethernet attached event for wan Feb 7 03:19:49 pfsense check_reload_status[396]: Reloading filter Feb 7 03:19:49 pfsense php-fpm[43269]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 7 03:19:49 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:19:49 pfsense php-fpm[43269]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 7 03:19:49 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 7 03:19:50 pfsense php-fpm[40797]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:19:50 pfsense php-fpm[40797]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:19:50 pfsense check_reload_status[396]: Reloading filter Feb 7 03:19:53 pfsense php-fpm[43269]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:19:54 pfsense check_reload_status[396]: updating dyndns wan Feb 7 03:20:00 pfsense root[51908]: ***** 23/02/07-03:20:00-WAN is down-VPN restart not attempted. Feb 7 03:20:00 pfsense root[57056]: ~~~~~ 23/02/07-03:20:00-WAN is down-DNS restart not attempted. Feb 7 03:20:28 pfsense php-fpm[43269]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1675758028] unbound[14790:0] error: bind: address already in use [1675758028] unbound[14790:0] fatal error: could not open ports' Feb 7 03:20:29 pfsense php-fpm[43269]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:20:29 pfsense check_reload_status[396]: Reloading filter Feb 7 03:24:00 pfsense root[32863]: ~~~~~ 23/02/07-03:24:00-WAN is down-DNS restart not attempted. Feb 7 03:25:00 pfsense sshguard[3413]: Exiting on signal. Feb 7 03:25:00 pfsense sshguard[67878]: Now monitoring attacks. Feb 7 03:25:00 pfsense root[72988]: ***** 23/02/07-03:25:00-WAN is down-VPN restart not attempted. Feb 7 03:28:00 pfsense root[87376]: ~~~~~ 23/02/07-03:28:00-WAN is down-DNS restart not attempted. Feb 7 03:30:00 pfsense root[45587]: ***** 23/02/07-03:30:00-WAN is down-VPN restart not attempted. Feb 7 03:32:00 pfsense root[93385]: ~~~~~ 23/02/07-03:32:00-WAN is down-DNS restart not attempted. Feb 7 03:35:00 pfsense root[55392]: ***** 23/02/07-03:35:00-WAN is down-VPN restart not attempted. Feb 7 03:36:00 pfsense root[6506]: ~~~~~ 23/02/07-03:36:00-WAN is down-DNS restart not attempted. Feb 7 03:37:51 pfsense php-fpm[40797]: /status_interfaces.php: The command '/usr/local/bin/dpinger -S -r 0 -i WAN_DHCP -B 99.xxx.xxx.xxx -p /var/run/dpinger_WAN_DHCP~99.xxx.xxx.xxx~8.8.8.8.pid -u /var/run/dpinger_WAN_DHCP~99.xxx.xxx.xxx~8.8.8.8.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 8.8.8.8 >/dev/null' returned exit code '1', the output was '' Feb 7 03:37:51 pfsense php-fpm[40797]: /status_interfaces.php: Error starting gateway monitor for WAN_DHCP Feb 7 03:37:55 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:37:56 pfsense php-fpm[43269]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:37:56 pfsense php-fpm[43269]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:37:56 pfsense check_reload_status[396]: Reloading filter Feb 7 03:39:49 pfsense sshd[33792]: Accepted password for admin_user from 172.16.50.16 port 33858 ssh2 Feb 7 03:40:00 pfsense root[76257]: ~~~~~ 23/02/07-03:40:00-WAN is down-DNS restart not attempted. Feb 7 03:40:00 pfsense root[77928]: ***** 23/02/07-03:40:00-WAN is down-VPN restart not attempted. Feb 7 03:40:55 pfsense admin_user[6885]: /usr/sbin/service: WARNING: $createswap_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 pfsense admin_user[7796]: /usr/sbin/service: WARNING: $expiretable_enable is not set properly - see rc.conf(5). Feb 7 03:19:49 pfsense php-fpm[43269]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 7 03:19:49 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:19:49 pfsense php-fpm[43269]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 7 03:19:49 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 7 03:19:50 pfsense php-fpm[40797]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:19:50 pfsense php-fpm[40797]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:19:50 pfsense check_reload_status[396]: Reloading filter Feb 7 03:19:53 pfsense php-fpm[43269]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the o utput was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:19:54 pfsense check_reload_status[396]: updating dyndns wan Feb 7 03:20:00 pfsense root[51908]: ***** 23/02/07-03:20:00-WAN is down-VPN restart not attempted. Feb 7 03:20:00 pfsense root[57056]: ~~~~~ 23/02/07-03:20:00-WAN is down-DNS restart not attempted. Feb 7 03:20:28 pfsense php-fpm[43269]: /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1675758028] unbound[14790:0] error: bind: address already in use [1675758028] unbound[14790:0] fatal error: could not open ports' Feb 7 03:20:29 pfsense php-fpm[43269]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the o utput was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:20:29 pfsense check_reload_status[396]: Reloading filter Feb 7 03:24:00 pfsense root[32863]: ~~~~~ 23/02/07-03:24:00-WAN is down-DNS restart not attempted. Feb 7 03:25:00 pfsense sshguard[3413]: Exiting on signal. Feb 7 03:25:00 pfsense sshguard[67878]: Now monitoring attacks. Feb 7 03:25:00 pfsense root[72988]: ***** 23/02/07-03:25:00-WAN is down-VPN restart not attempted. Feb 7 03:28:00 pfsense root[87376]: ~~~~~ 23/02/07-03:28:00-WAN is down-DNS restart not attempted. Feb 7 03:30:00 pfsense root[45587]: ***** 23/02/07-03:30:00-WAN is down-VPN restart not attempted. Feb 7 03:32:00 pfsense root[93385]: ~~~~~ 23/02/07-03:32:00-WAN is down-DNS restart not attempted. Feb 7 03:35:00 pfsense root[55392]: ***** 23/02/07-03:35:00-WAN is down-VPN restart not attempted. Feb 7 03:36:00 pfsense root[6506]: ~~~~~ 23/02/07-03:36:00-WAN is down-DNS restart not attempted. Feb 7 03:37:51 pfsense php-fpm[40797]: /status_interfaces.php: The command '/usr/local/bin/dpinger -S -r 0 -i WAN_DHCP -B 99.xxx.xxx.xxx -p /var/ run/dpinger_WAN_DHCP~99.xxx.xxx.xxx~8.8.8.8.pid -u /var/run/dpinger_WAN_DHCP~99.xxx.xxx.xxx~8.8.8.8.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 8.8.8.8 >/dev/null' returned exit code '1', the output was '' Feb 7 03:37:51 pfsense php-fpm[40797]: /status_interfaces.php: Error starting gateway monitor for WAN_DHCP Feb 7 03:37:55 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 7 03:37:56 pfsense php-fpm[43269]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 7 03:37:56 pfsense php-fpm[43269]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 7 03:37:56 pfsense check_reload_status[396]: Reloading filter Feb 7 03:39:49 pfsense sshd[33792]: Accepted password for admin_user from 172.16.50.16 port 33858 ssh2 Feb 7 03:40:00 pfsense root[76257]: ~~~~~ 23/02/07-03:40:00-WAN is down-DNS restart not attempted. Feb 7 03:40:00 pfsense root[77928]: ***** 23/02/07-03:40:00-WAN is down-VPN restart not attempted. Feb 7 03:40:55 pfsense admin_user[6885]: /usr/sbin/service: WARNING: $createswap_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 pfsense admin_user[7796]: /usr/sbin/service: WARNING: $expiretable_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 pfsense admin_user[16522]: /usr/sbin/service: WARNING: $microcode_update_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 pfsense admin_user[28274]: /usr/sbin/service: WARNING: $uuidd_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 pfsense admin_user[30895]: /usr/sbin/service: WARNING: $ is not set properly - see rc.conf(5). Feb 7 03:40:55 guardian admin_user[35972]: /usr/sbin/service: WARNING: $dhcp6c_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 guardian admin_user[38957]: /usr/sbin/service: WARNING: $mpd_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 guardian admin_user[46571]: /usr/sbin/service: WARNING: $unbound_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 guardian admin_user[49061]: /usr/sbin/service: WARNING: $radvd_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 guardian admin_user[52606]: /usr/sbin/service: WARNING: $igmpproxy_enable is not set properly - see rc.conf(5). Feb 7 03:40:55 guardian admin_user[60088]: /usr/sbin/service: WARNING: $syslog_ng_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[71986]: /usr/sbin/service: WARNING: $smartd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[80691]: /usr/sbin/service: WARNING: $dnsmasq_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[84434]: /usr/sbin/service: WARNING: $rrdcached_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[85074]: /usr/sbin/service: WARNING: $rrdcached_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[85981]: /usr/sbin/service: WARNING: $openvpn_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[87039]: /usr/sbin/service: WARNING: $miniupnpd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[87468]: /usr/sbin/service: WARNING: $miniupnpd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[87859]: /usr/sbin/service: WARNING: $dbus_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[88851]: /usr/sbin/service: WARNING: $dhcpd6_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[89526]: /usr/sbin/service: WARNING: $dhcpd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[90692]: /usr/sbin/service: WARNING: $dhcp6s_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[91564]: /usr/sbin/service: WARNING: $dhcp6relay_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[98706]: /usr/sbin/service: WARNING: $strongswan_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[165]: /usr/sbin/service: WARNING: $xinetd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[1193]: /usr/sbin/service: WARNING: $pcscd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[2222]: /usr/sbin/service: WARNING: $nginx_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[3232]: /usr/sbin/service: WARNING: $scponlyc_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[4041]: /usr/sbin/service: WARNING: $lighttpd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[5510]: /usr/sbin/service: WARNING: $rsyncd_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[6282]: /usr/sbin/service: WARNING: $sshguard_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[9790]: /usr/sbin/service: WARNING: $darkstat_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[11402]: /usr/sbin/service: WARNING: $choparp_enable is not set properly - see rc.conf(5). Feb 7 03:40:56 guardian admin_user[14357]: /usr/sbin/service: WARNING: $php_fpm_enable is not set properly - see rc.conf(5). Feb 7 03:41:44 guardian sudo[8114]: admin_user : TTY=pts/0 ; PWD=/home/admin_user ; USER=root ; COMMAND=/bin/tcsh Feb 7 03:44:00 guardian root[75739]: ~~~~~ 23/02/07-03:44:00-WAN is down-DNS restart not attempted. Feb 7 03:45:00 guardian root[39499]: ***** 23/02/07-03:45:00-WAN is down-VPN restart not attempted. Feb 7 03:48:00 guardian root[80908]: ~~~~~ 23/02/07-03:48:00-WAN is down-DNS restart not attempted. Feb 7 03:50:00 guardian root[77461]: ***** 23/02/07-03:50:00-WAN is down-VPN restart not attempted. Feb 7 03:52:00 guardian root[32549]: ~~~~~ 23/02/07-03:52:00-WAN is down-DNS restart not attempted. Feb 7 03:55:00 guardian root[13356]: ***** 23/02/07-03:55:00-WAN is down-VPN restart not attempted. Feb 7 03:55:40 guardian php-fpm[44538]: /status_services.php: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:e0:10:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 7 03:56:00 guardian root[33706]: ~~~~~ 23/02/07-03:56:00-WAN is down-DNS restart not attempted. Feb 7 04:00:00 guardian root[51358]: ~~~~~ 23/02/07-04:00:00-WAN is down-DNS restart not attempted.Any ideas?
-
@guardian This thread maybe relevant https://forum.netgate.com/topic/169614/wan-does-not-renew-after-reboot
-
So you could see dpinger wasn't running? No monitoring pings in the states or packet capture?
The first thing I would do here is disable whatever is generating these logs:
Feb 7 03:44:00 guardian root[75739]: ~~~~~ 23/02/07-03:44:00-WAN is down-DNS restart not attempted. Feb 7 03:45:00 guardian root[39499]: ***** 23/02/07-03:45:00-WAN is down-VPN restart not attempted.You see to have far more things happening there than I would expect for a simple link bounce.
The logs show the last actual link event here when the WAN came back up:Feb 7 03:15:38 pfsense kernel: em0: link state changed to UPBut the linkup scripts are still running ~30min later. Something there is getting stuck or looping.
That custom script has to be the first suspect.Steve
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
So you could see dpinger wasn't running? No monitoring pings in the states or packet capture?
The first thing I would do here is disable whatever is generating these logs:
Feb 7 03:44:00 guardian root[75739]: ~~~~~ 23/02/07-03:44:00-WAN is down-DNS restart not attempted. Feb 7 03:45:00 guardian root[39499]: ***** 23/02/07-03:45:00-WAN is down-VPN restart not attempted.You see to have far more things happening there than I would expect for a simple link bounce.
The logs show the last actual link event here when the WAN came back up:Feb 7 03:15:38 pfsense kernel: em0: link state changed to UPBut the linkup scripts are still running ~30min later. Something there is getting stuck or looping.
That custom script has to be the first suspect.Thanks Steve ( @stephenw10 ) I've had a similar issue for a long time, that DNS and/or VPN would go offline. These watchdog
scripts have been working for several years, and in this case they have not done anything (whenever they do something they emit a log message). Your suggestion has prompted me to modify the cron times slightly just in case the both of them are interfering with each other. The current cron is */5 * * * * for the DNS, and OpenVPN restart. I've changed the OpenVPN to 1,6,11,16,21,26,31,36,41,51,56 * * * * so that gives unbound a minute to restart before trying to restart OpenVPN.Both scripts rely on a call to pfSsh.php playback gatewaystatus and the output is parsed for the status of OpenVPN gateway or the WAN as required.
# Name Monitor Source Delay StdDev Loss Status Substatus # UDP_TOS_VPNV4 8.8.4.4 xx.xx.xxx.xx 54.926ms 11.309ms 0.0% online none # WAN_DHCP 8.8.8.8 xx.xxx.xxx.xxx 16.37ms 2.843ms 0.0% online noneIf the WAN is not showing as online then both scripts do nothing.
The DNS restart script does a dig on cloudflare.com, and if the search fails, it does a
/usr/local/sbin/pfSsh.php playback svc restart unboundcommand to restart unbound.
The OpenVPN script checks the gateway status, and if the VPN shows as down it then checks if the WAN is UP before it attempts to restart the OpenVPN. So if dpinger is out, then both my watchdogs are useless and turn into NOPs.
I think there is something that is killing dpinger, or there is some sort of issue with the port/network stack.
Thoughts/Comments?
-
So to be clear you are actually seeing dpinger not running?
Like no outbound state and/or no pings in a pcap?
It looks like some race condition you're hitting where the link flapping causes numerous restarts and when dpinger tries to restart the link is down again so it fails out.
When you're in that state if you just start dpinger from Status > Services does it start normally?
-
@guardian said in pfSense 2.6.0 Fails to Recover after WAN Issues:
I am running pfSese 2.6.0 Community edition, and for the most part it has been very stable with the exception of a random issue that occurs from time to time when there are issues with my cable internet provider (Rogers in Canada).
I am also running a VPN client with policy routing that routes traffic from some machines though a VPN.
Over the last couple of days there have been short problems on the WAN, but for some reason the VPN doesn't recover.
When I log in to the webgui (which takes a very long time to respond), the dpinger widget shows both the WAN and VPN as down. However the WAN is NOT DOWN. Machines that are not routed though the VPN work normally, and I can run ping from the command shell and the WAN is passing traffic normally.
If it was just a matter of the VPN, I wrote a small script that runs every 5 minutes that restarts OpenVPN if I can't ping trough the VPN, but that script will not run (by design) if the WAN is down.
The link status incorrectly appearing as down is likely what is causing issues with OpenVPN, and possibly DNS
Any suggestions as to how I might go about troubleshooting this issue.
@stephenw10 thanks for hanging in there with me on this - I really appreciate it.
I did the pcap not on the last, but second last incident, and there was nothing going out. In this case there was nothing but ARPs in the pcap.
The last time, I didn't think to run the pcap again, because Status > Services showed dpinger/dns/openvpn as not running. I clicked the start for each one, and everything was running normally again. Jjust for good measure I did a reboot in case something was corrupted.
After reading your feedback, I took a look at the log again, and this pattern:
Feb 7 03:13:13 pfsense php-fpm[358]: /rc.linkup: DEVD Ethernet detached event for wan
[ ---- Deleted Lines----]
Feb 7 03:13:16 pfsense php-fpm[44538]: /rc.linkup: DEVD Ethernet attached event for wan
Feb 7 03:13:16 pfsense php-fpm[44538]: /rc.linkup: HOTPLUG: Configuring interface wanleads me to believe that the issue was the WAN isn't coming up, and that caused a cascading failure.
The WAN is a Hitron CODA-4582U cable modem operating in bridge mode. I haven't heard of Hitron, but I'm betting it's not great quantity, and the modem may be doing something strange especially at the time it goes offline, or when it comes online gain.
(Since connectivity is generally good, I think the outages are maintenace or possibly when the lease expires.)I took a look at /etc/rc.linkup, and I see that it tries to restart unbound after restarting the interface, but I can't tell if the restart attempt happens if the interface doesn't properly recover since I don't have enough understanding of the context and what all the variables mean.
It looks like a pfBlocker update starts to run while the WAN is down, which may end up putting some stress on the system that causes corruption.
A possible hypothesises is the WAN goes down and doesn't come back up before pfBlocker update runs, then the system doesn't recover.
Also what about this comment from @Patch :
@patch said in pfSense 2.6.0 Fails to Recover after WAN Issues:@guardian This thread maybe relevant https://forum.netgate.com/topic/169614/wan-does-not-renew-after-reboot
As I previously mentioned, this has been an issue for a long time, but until recently my "watchdog" scripts have been solving the problem -- it's just recently that I have noticed that dpinger hasn't recovered.
Thoughts/Comments?
P.S.: As an aside, when connectivity is down, it takes about a minute to log in before the dashboard appears, and there is no feedback that the login button has accepted the click. I suspect that all the widgets that aren't working because the WAN is down are blocking login. This might not be a bad thing to fix. I find myself going in with SSH to find out if the box is alive since the GUI takes so long to come up. If top looks normal, I then try a ping on 8.8.8.8, and by then the GUI MAY be up.
If you find my post useful, please give it a thumbs up!
pfSense 2.7.2-RELEASE -
Mmm, this looks to me like too many things trying to restart in quick succession resulting in a an unexpected condition.
I imagine if you manually disconnect the WAN cable wait 10s then reconnect it the services should recover as expected. Are you able to try that?
It's the flapping link that is causing this:
Feb 7 03:13:12 pfsense kernel: em0: link state changed to DOWN Feb 7 03:13:15 pfsense kernel: em0: link state changed to UP Feb 7 03:13:16 pfsense kernel: em0: link state changed to DOWN Feb 7 03:13:19 pfsense kernel: em0: link state changed to UP Feb 7 03:14:22 pfsense kernel: em0: link state changed to DOWN Feb 7 03:14:24 pfsense kernel: em0: link state changed to UP Feb 7 03:14:25 pfsense kernel: em0: link state changed to DOWN Feb 7 03:14:29 pfsense kernel: em0: link state changed to UP Feb 7 03:15:32 pfsense kernel: em0: link state changed to DOWN Feb 7 03:15:38 pfsense kernel: em0: link state changed to UPThough I agree pfSense should handle this better.
You might also try just rebooting the modem to see how many time the link cycles when it boots as expected.
Steve
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
Mmm, this looks to me like too many things trying to restart in quick succession resulting in a an unexpected condition.
I imagine if you manually disconnect the WAN cable wait 10s then reconnect it the services should recover as expected. Are you able to try that?
I'll keep that in mind for the next time it happens. I'll try unplugging the cable from the modem while it is rebooting, and then plug it in after the modem status lights show connectivity has been restored (Usually about 3-5 minutes).
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
Though I agree pfSense should handle this better.
You might also try just rebooting the modem to see how many time the link cycles when it boots as expected.
I actually did try rebooting the modem. Even after the system had been functional (with OpenVPN, unbound or both down) for some time, dpinger didn't come back.
EDIT:
Is dpinger always supposed to be running on a properly functioning system?If so, is there any type of watchdog to restart it if it fails?
If not, I was thinking about another script for myself that would check for the presence of processes using ps auxww that contained/usr/local/bin/dpinger. The command line is available and contains the name of the interface so it is easy to test for. How can I restart dpinger from the shell?
So I would have a series of watchdogs: (at minutes past the hour)
5,10,15... : Check if dpinger down, if so restart it.
6,11,16... : Check if unbound down, if so restart it.
7,12,17... : Check if OpenVPN down, if so restart it.
It would be better if the system could protect itself, and possibly provide a flag for plugin authors that they should avoid going out to the internet of connectivity is down.I just remembered this post by @michmoor
@michmoor said in pfSense 2.6.0 Fails to Recover after WAN Issues:- Install the Watchdog service: have it monitor your OpenVPN client. If it detects it down it will restart automatically.
So I have downloaded and installed the package he suggested and configured it to monitor dpinger, unbound and openvpn and removed the cron entries for my scripts. It will be interesting to see if this improves the situation or makes things worse.
Is there any flag available in the code that other apps could use to determine if the WAN is down?
I guess the hardest part of this is that there are so many different use cases that it may be hard to know which interfaces are important for providing internet connectivity. If it can't be determined heuristically , this could be configuration data provided in the GUI.@stephenw10 just wondering do any coding on pfSense? (IIUC you work for Netgate).
I'm assuming that most of Netgate's commercial customers running pfSense are not using heavy plugins and that they likely have redundant hardware and an external watchdog that would reboot a malfunctioning box -- hence this isn't a high priority problem. I'm wondering if @jimp might have something to say on this issue.
////// Aside
Anyway just to be absolutely clear my continued dialog is not intended as criticism -- I am very grateful for Netgate's generosity in supporting this project as open source and only want to solve my issue and hopefully contribute something that might improve things for everyone. -
Your configuration is not unusual. What is unusual is that when the modem has issues it appears to be linking and unlinking multiple times in quick succession. That is triggering a race condition of sorts that ends up without services running.
If you put a switch between the WAN NIC and the modem for example that would almost certainly eliminate this issue.
But testing to see what happens in a controlled situation such as manually reconnecting the WAN cable or rebooting the modem could give some useful data. If the WAN does not flap when doing that then it's something the modem is doing when it fails. -
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
If you put a switch between the WAN NIC and the modem for example that would almost certainly eliminate this issue.
Interesting idea... I don't have a spare switch at the moment, but I will keep that in mind.But testing to see what happens in a controlled situation such as manually reconnecting the WAN cable or rebooting the modem could give some useful data. If the WAN does not flap when doing that then it's something the modem is doing when it fails.
Hi @stephenw10 OK, I took a few minutes to do some testing, and the TLDR; appears to be that there is something about the way the link on the cable modem comes back up after a reboot.
What I did was to disconnect the cable for 10 minutes and reconnect it without rebooting the modem. The system recovered normally after a couple of minutes.
Then I pulled the power on the modem for 30 seconds and let the modem reboot. The system did not properly recover until I pulled the plug and disconnected the modem from pfSense. I suspect that the modem is restoring link connectivity before the internet connectivity returns, but this is just a guess.
FWIW, here is the log form both tests - I used logger as admin_user from the console to inject a few messages as comments for reference.
Feb 12 03:49:19 pfsense admin_user[16594]: ********************************************************************** Feb 12 03:50:04 pfsense kernel: em0: link state changed to DOWN Feb 12 03:50:04 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 03:50:05 pfsense php-fpm[22688]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 03:50:06 pfsense php-fpm[22688]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.2.110.27 Feb 12 03:50:06 pfsense check_reload_status[396]: Reloading filter Feb 12 03:50:07 pfsense admin_user[96112]: Disconnecting network cable from modem Feb 12 03:50:08 pfsense rc.gateway_alarm[99539]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 03:50:08 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 03:50:08 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 03:50:08 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 03:50:08 pfsense check_reload_status[396]: Reloading filter Feb 12 03:50:09 pfsense php-fpm[91128]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 03:50:09 pfsense php-fpm[91128]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 03:51:08 pfsense kernel: ovpnc1: link state changed to DOWN Feb 12 03:51:08 pfsense check_reload_status[396]: Reloading filter Feb 12 03:52:00 pfsense php[41801]: servicewatchdog_cron.php: Service Watchdog detected service openvpn stopped. Restarting openvpn (OpenVPN client: VPN STRONG UDP (1197)) Feb 12 03:52:00 pfsense root[48667]: ~~~~~ 23/02/12-03:52:00-WAN is down-DNS restart not attempted. Feb 12 03:52:00 pfsense check_reload_status[396]: Reloading filter Feb 12 03:52:00 pfsense php[48999]: notify_monitor.php: Could not send the message to pfsense@qsv.ca -- Error: Failed to connect to ssl://shadow.mxrouting.net:465 [SMTP: Failed to connect socket: Network is unreachable (code: -1, response: )] Feb 12 03:53:42 pfsense php-fpm[359]: /packages/cron/cron_edit.php: Configuration Change: admin_user@172.16.50.16 (Local Database): Crontab item deleted via cron package Feb 12 03:53:42 pfsense check_reload_status[396]: Syncing firewall Feb 12 04:01:09 pfsense admin_user[99346]: Reconnecting network cable to modem Feb 12 04:01:15 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:01:15 pfsense kernel: em0: link state changed to UP Feb 12 04:01:16 pfsense php-fpm[22688]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:01:16 pfsense php-fpm[22688]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:01:16 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:01:16 pfsense php-fpm[22688]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:01:16 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:01:17 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:01:17 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:01:17 pfsense check_reload_status[396]: Reloading filter Feb 12 04:01:23 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:01:23 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:01:57 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:01:58 pfsense check_reload_status[396]: Reloading filter Feb 12 04:02:32 pfsense kernel: ovpnc1: link state changed to UP Feb 12 04:02:32 pfsense check_reload_status[396]: rc.newwanip starting ovpnc1 Feb 12 04:02:33 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: Info: starting on ovpnc1. Feb 12 04:02:33 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: on (IP address: 10.28.110.16) (interface: UDP_TOS[opt28]) (real interface: ovpnc1). Feb 12 04:02:39 pfsense php-fpm[4753]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 99.xxx.xxx.1 Feb 12 04:02:39 pfsense php-fpm[4753]: /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:02:40 pfsense php-fpm[4753]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:02:40 pfsense php-fpm[4753]: /rc.newwanip: IP Address has changed, killing states on former IP Address 10.2.110.27. Feb 12 04:02:46 pfsense php-fpm[4753]: /rc.newwanip: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:02:46 pfsense php-fpm[4753]: /rc.newwanip: Creating rrd update script Feb 12 04:02:48 pfsense php-fpm[4753]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.2.110.27 -> 10.28.110.16 - Restarting packages. Feb 12 04:02:48 pfsense check_reload_status[396]: Starting packages Feb 12 04:02:49 pfsense php-fpm[91128]: /rc.start_packages: Restarting/Starting all packages. Feb 12 04:02:50 pfsense php-fpm[91128]: /rc.start_packages: Reloading syslog-ng for configuration sync Feb 12 04:02:50 pfsense supervise/syslog-ng[19818]: Daemon exited gracefully, not restarting; exitcode='0' Feb 12 04:02:55 pfsense php-fpm[91128]: /rc.start_packages: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was '' Feb 12 04:02:56 pfsense check_reload_status[396]: Reloading filter Feb 12 04:02:56 pfsense kernel: em1.1: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.91: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.92: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.93: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.10: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.192: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.254: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.20: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.30: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.40: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1.50: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em0: promiscuous mode disabled Feb 12 04:02:56 pfsense kernel: em1: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.1: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.91: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.92: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.93: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.10: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.192: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.254: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.20: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.30: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.40: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em1.50: promiscuous mode enabled Feb 12 04:02:56 pfsense kernel: em0: promiscuous mode enabled Feb 12 04:02:59 pfsense lighttpd_pfb[4133]: [pfBlockerNG] DNSBL Webserver stopped Feb 12 04:02:59 pfsense tail_pfb[4327]: [pfBlockerNG] Firewall Filter Service stopped Feb 12 04:02:59 pfsense php_pfb[4627]: [pfBlockerNG] filterlog daemon stopped Feb 12 04:02:59 pfsense lighttpd_pfb[6129]: [pfBlockerNG] DNSBL Webserver started Feb 12 04:02:59 pfsense tail_pfb[9019]: [pfBlockerNG] Firewall Filter Service started Feb 12 04:03:00 pfsense php[6968]: [pfBlockerNG] DNSBL parser daemon started Feb 12 04:03:00 pfsense php[9363]: [pfBlockerNG] filterlog daemon started Feb 12 04:03:38 pfsense admin_user[45430]: Dashboard shows everything back online - Testing complete Feb 12 04:03:41 pfsense admin_user[47476]: ********************************************************************** Feb 12 04:05:18 pfsense admin_user[16322]: ********************************************************************** Feb 12 04:05:27 pfsense admin_user[18252]: reboooting modem Feb 12 04:05:34 pfsense kernel: em0: link state changed to DOWN Feb 12 04:05:34 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:05:35 pfsense php-fpm[4753]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:05:36 pfsense php-fpm[4753]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:05:36 pfsense check_reload_status[396]: Reloading filter Feb 12 04:05:38 pfsense rc.gateway_alarm[29450]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:05:38 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:05:38 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:05:38 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:05:38 pfsense check_reload_status[396]: Reloading filter Feb 12 04:05:39 pfsense php-fpm[38038]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:05:39 pfsense php-fpm[38038]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:05:46 pfsense admin_user[9863]: modem power off Feb 12 04:06:15 pfsense admin_user[75447]: modem power on Feb 12 04:06:19 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:06:19 pfsense kernel: em0: link state changed to UP Feb 12 04:06:20 pfsense php-fpm[359]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:06:20 pfsense php-fpm[359]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:07:21 pfsense kernel: em0: link state changed to DOWN Feb 12 04:07:21 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:07:30 pfsense kernel: em0: link state changed to UP Feb 12 04:07:30 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:08:01 pfsense admin_user[85736]: modem all lights flashed Feb 12 04:08:26 pfsense kernel: em0: link state changed to DOWN Feb 12 04:08:26 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:08:33 pfsense kernel: em0: link state changed to UP Feb 12 04:08:33 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:09:52 pfsense php-fpm[359]: /rc.linkup: Default gateway setting Interface WAN_DHCP Gateway as default. Feb 12 04:09:52 pfsense php-fpm[359]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:09:52 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:09:58 pfsense php-fpm[359]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:09:58 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:10:07 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:10:08 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:10:08 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:10:08 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:11 pfsense admin_user[46872]: modem status lights indicate connectivity restored Feb 12 04:10:33 pfsense php-fpm[359]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:10:33 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:33 pfsense php-fpm[74959]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:10:34 pfsense php-fpm[74959]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:10:34 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:34 pfsense php-fpm[22688]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:10:34 pfsense php-fpm[22688]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:10:35 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:10:36 pfsense php-fpm[359]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:10:36 pfsense php-fpm[359]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:10:36 pfsense check_reload_status[396]: Reloading filter Feb 12 04:10:37 pfsense rc.gateway_alarm[76647]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:10:37 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:10:37 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:10:37 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:10:37 pfsense php-fpm[22688]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:10:37 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:10:38 pfsense php-fpm[74959]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:10:38 pfsense php-fpm[74959]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:11:11 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:11:12 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:11:46 pfsense php-fpm[22688]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:11:47 pfsense check_reload_status[396]: Reloading filter Feb 12 04:11:47 pfsense php-fpm[38038]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:11:48 pfsense php-fpm[38038]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:11:48 pfsense php-fpm[17557]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:11:48 pfsense check_reload_status[396]: Reloading filter Feb 12 04:11:48 pfsense php-fpm[17557]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:11:48 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:11:48 pfsense php-fpm[17557]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:11:48 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:11:49 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:11:49 pfsense php-fpm[91128]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:11:49 pfsense check_reload_status[396]: Reloading filter Feb 12 04:11:50 pfsense rc.gateway_alarm[53702]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:11:50 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:11:50 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:11:50 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:11:51 pfsense php-fpm[22688]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:11:51 pfsense php-fpm[22688]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:12:23 pfsense php-fpm[17557]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:12:23 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:12:24 pfsense admin_user[32234]: dashboard indicates WAN Unknown / OpenVPN OFFLINE Feb 12 04:12:58 pfsense php-fpm[17557]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:12:58 pfsense check_reload_status[396]: Reloading filter Feb 12 04:15:00 pfsense php[31842]: [pfBlockerNG] Starting cron process. Feb 12 04:16:08 pfsense admin_user[63130]: pfBlocker Update started / Dashboard indicates WAN/OpenVPN Down Feb 12 04:16:14 pfsense kernel: em0: link state changed to DOWN Feb 12 04:16:14 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:16:15 pfsense php-fpm[38038]: /rc.linkup: DEVD Ethernet detached event for wan Feb 12 04:16:16 pfsense php-fpm[38038]: /rc.linkup: Removing static route for monitor 8.8.4.4 and adding a new route through 10.28.110.16 Feb 12 04:16:16 pfsense check_reload_status[396]: Reloading filter Feb 12 04:16:18 pfsense rc.gateway_alarm[24348]: >>> Gateway alarm: UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Feb 12 04:16:18 pfsense check_reload_status[396]: updating dyndns UDP_TOS_VPNV4 Feb 12 04:16:18 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:16:18 pfsense check_reload_status[396]: Restarting OpenVPN tunnels/interfaces Feb 12 04:16:18 pfsense check_reload_status[396]: Reloading filter Feb 12 04:16:19 pfsense php-fpm[22688]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:16:19 pfsense php-fpm[22688]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use UDP_TOS_VPNV4. Feb 12 04:16:29 pfsense admin_user[88035]: Cable disconnected from modem Feb 12 04:16:54 pfsense admin_user[85547]: Cable reconnected to modem Feb 12 04:16:55 pfsense check_reload_status[396]: Linkup starting em0 Feb 12 04:16:55 pfsense kernel: em0: link state changed to UP Feb 12 04:16:56 pfsense php-fpm[76071]: /rc.linkup: DEVD Ethernet attached event for wan Feb 12 04:16:56 pfsense php-fpm[76071]: /rc.linkup: HOTPLUG: Configuring interface wan Feb 12 04:16:56 pfsense check_reload_status[396]: rc.newwanip starting em0 Feb 12 04:16:56 pfsense php-fpm[76071]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:16:56 pfsense check_reload_status[396]: Restarting IPsec tunnels Feb 12 04:16:57 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: Info: starting on em0. Feb 12 04:16:57 pfsense php-fpm[4753]: /rc.newwanip: rc.newwanip: on (IP address: 99.xxx.xxx.xxx) (interface: WAN[wan]) (real interface: em0). Feb 12 04:16:57 pfsense check_reload_status[396]: Reloading filter Feb 12 04:17:03 pfsense php-fpm[76071]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:17:03 pfsense check_reload_status[396]: updating dyndns wan Feb 12 04:17:38 pfsense php-fpm[76071]: /rc.linkup: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:17:38 pfsense check_reload_status[396]: Reloading filter Feb 12 04:18:24 pfsense kernel: ovpnc1: link state changed to DOWN Feb 12 04:18:24 pfsense check_reload_status[396]: Reloading filter Feb 12 04:18:25 pfsense kernel: ovpnc1: link state changed to UP Feb 12 04:18:25 pfsense check_reload_status[396]: rc.newwanip starting ovpnc1 Feb 12 04:18:27 pfsense php-fpm[17557]: /rc.newwanip: rc.newwanip: Info: starting on ovpnc1. Feb 12 04:18:27 pfsense php-fpm[17557]: /rc.newwanip: rc.newwanip: on (IP address: 10.16.110.16) (interface: UDP_TOS[opt28]) (real interface: ovpnc1). Feb 12 04:18:37 pfsense php-fpm[17557]: /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 99.xxx.xxx.1 Feb 12 04:18:38 pfsense php-fpm[17557]: /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.16.110.16 Feb 12 04:18:38 pfsense php-fpm[17557]: /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. '' Feb 12 04:18:38 pfsense php-fpm[17557]: /rc.newwanip: IP Address has changed, killing states on former IP Address 10.28.110.16. Feb 12 04:18:43 pfsense php[31842]: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Feb 12 04:18:43 pfsense php[31842]: Feb 12 04:18:45 pfsense php-fpm[17557]: /rc.newwanip: The command '/usr/sbin/arp -s '172.16.50.1' '00:28:1a:xx:xx:xx'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Feb 12 04:18:45 pfsense php-fpm[17557]: /rc.newwanip: Creating rrd update script Feb 12 04:18:47 pfsense php-fpm[17557]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.28.110.16 -> 10.16.110.16 - Restarting packages. Feb 12 04:18:47 pfsense check_reload_status[396]: Starting packages Feb 12 04:18:48 pfsense php-fpm[38038]: /rc.start_packages: Restarting/Starting all packages. Feb 12 04:18:49 pfsense php-fpm[38038]: /rc.start_packages: Reloading syslog-ng for configuration sync Feb 12 04:18:49 pfsense supervise/syslog-ng[17474]: Daemon exited gracefully, not restarting; exitcode='0' Feb 12 04:18:54 pfsense php-fpm[38038]: /rc.start_packages: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was '' Feb 12 04:18:55 pfsense check_reload_status[396]: Reloading filter Feb 12 04:18:55 pfsense kernel: em1.1: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.91: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.92: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.93: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.10: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.192: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.254: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.20: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.30: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.40: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1.50: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em0: promiscuous mode disabled Feb 12 04:18:55 pfsense kernel: em1: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.1: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.91: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.92: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.93: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.10: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.192: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.254: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.20: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.30: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.40: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em1.50: promiscuous mode enabled Feb 12 04:18:55 pfsense kernel: em0: promiscuous mode enabled Feb 12 04:18:55 pfsense admin_user[51191]: Dashboard shows WAN/OPENVPN now oline Feb 12 04:18:57 pfsense tail_pfb[32202]: [pfBlockerNG] Firewall Filter Service stopped Feb 12 04:18:57 pfsense php_pfb[32309]: [pfBlockerNG] filterlog daemon stopped Feb 12 04:18:58 pfsense lighttpd_pfb[33446]: [pfBlockerNG] DNSBL Webserver stopped Feb 12 04:18:58 pfsense lighttpd_pfb[35056]: [pfBlockerNG] DNSBL Webserver started Feb 12 04:18:58 pfsense tail_pfb[38719]: [pfBlockerNG] Firewall Filter Service started Feb 12 04:18:58 pfsense php[35803]: [pfBlockerNG] DNSBL parser daemon started Feb 12 04:18:59 pfsense php[39232]: [pfBlockerNG] filterlog daemon started Feb 12 04:21:19 pfsense admin_user[22342]: pfBlocker-- Unable to apply rules. Outbound interface option not configured. Feb 12 04:21:33 pfsense admin_user[23930]: System Normal - testing complete Feb 12 04:21:40 pfsense admin_user[24890]: **********************************************************************Any ideas? Any way of monitoring status registers on the WAN NIC? It is also possible that some IPv6 signalling is expected, but I have IPv6 turned off on interrfaces for security reasons as I don't trust myself to deal with it properly.
P.S: Rogers has been quite scary in the past with IPv6 in the past - at one point a couple of years back, default configuration of their modem and default configuration of Windows had everyone's shares exposed to the internet.
-
I would test putting a switch between the modem and pfSense and seeing if that eliminates the issue when rebooting the modem. I would expect it to.
-
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
I would test putting a switch between the modem and pfSense and seeing if that eliminates the issue when rebooting the modem. I would expect it to.
At the moment I don't have a spare switch available to do that with. Any ideas as to how I might test what is going on (shell script or small php script)? I deactivated my watchdog scripts in favor of the watchdog plugin to see how that works. I have noticed a couple of short gateway issues, but the didn't seem to persist.
I was thinking maybe if there was a loss of WAN connectivity for 5 minutes, but the WAN showed as up to down the interface for say 10-15 seconds and then bring it up again.
What is the best FreeBSD way to do that? Based on your knowledge of how the system works, is pfSense likely to bring the WAN back up? If so how quickly?
Thoughts?
-
FWIW, I'm on Rogers and find my service is extremely reliable. One thing you might want to check is the hardware. A flaky (pardon the technical jargon) computer or bad patch cord could cause problems.
-
You shouldn't need to do more than re-apply the WAN config.
So I'd first try:/etc/rc.linkup start wan -
@jknott said in pfSense 2.6.0 Fails to Recover after WAN Issues:
FWIW, I'm on Rogers and find my service is extremely reliable. One thing you might want to check is the hardware. A flaky (pardon the technical jargon) computer or bad patch cord could cause problems.
@jknott thanks for the reply. I agree the service is very reliable. I can go for months without a problem, then something happens (based on timing, I think it is likely maintenance), the service goes out, and doesn't recover. When I reboot the router, it appears that pfSense doesn't always come back without intervention.. When I did a reboot to test, I found in the trail that I did that pfSense did not come back online until I briefly disconnected the network cable briefly and then reconnected it. That leads me to the conclusion that there is something going on either at the output of the modem, or with the WAN port.
BTW what speed service/modem do you have. I have GB/Hitron CPDA-4582U.
If you find my post useful, please give it a thumbs up!
pfSense 2.7.2-RELEASE -
@stephenw10 said in pfSense 2.6.0 Fails to Recover after WAN Issues:
You shouldn't need to do more than re-apply the WAN config.
So I'd first try:/etc/rc.linkup start wan@stephenw10 - Thanks.... I'll keep that in mind. So far no further issues since my last report. I may go months (or minutes) before the next failure.
Any idea how I can test if dpinger is functioning correctly? I was thinking about a watchdog that would (assuming dpinger is OK) apply
/etc/rc.linkup start wanevery 5 minutes until things came back online. Thoughts?I'll likely pend this till the next time that I have issues.... likely be on a different version of pfSense by that time.
-
@guardian said in pfSense 2.6.0 Fails to Recover after WAN Issues:
@stephenw10 Things have been working well until today. Since you are part of the Netgate team, I though I should ping you on this issue since you were involved before, and maybe someone else might have some bright ideas as well. I've included the log from the relevent time frame at the bottom of this post.It appears that the watchdog plugin is not very useful at restarting the OpenVPN client. I had some issues on the WAN, that screwed up the VPN client: (I think this is what started it):
Mar 2 14:46:14 rc.gateway_alarm 5241 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:593.648ms RTTsd:1382.451ms Loss:0%)The WAN recovered, but the VPN didn't recover, which caused my wife to ask me to investigate. The WAN was UP, VPN was DOWN.
I looked in the OpenVPN log and found this:
Mar 2 17:10:40 openvpn 48841 MANAGEMENT: CMD 'status 2' Mar 2 17:10:40 openvpn 48841 MANAGEMENT: Client connected from /var/etc/openvpn/server4/sock Mar 2 17:10:40 openvpn 73327 MANAGEMENT: Client disconnected Mar 2 17:10:40 openvpn 73327 MANAGEMENT: CMD 'quit' Mar 2 17:10:39 openvpn 73327 MANAGEMENT: CMD 'status 2' Mar 2 17:10:39 openvpn 73327 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sock Mar 2 17:09:53 openvpn 48841 159.203.192.10:54092 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 17:09:53 openvpn 48841 159.203.192.10:54092 Connection reset, restarting [0] Mar 2 17:09:53 openvpn 48841 159.203.192.10:54092 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 17:09:53 openvpn 48841 TCP connection established with [AF_INET]159.203.192.10:54092 Mar 2 17:09:53 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:53 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:53 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:53 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:46 openvpn 48841 107.170.253.8:57982 SIGUSR1[soft,connection-reset] received, client-instance restarting Mar 2 17:09:46 openvpn 48841 107.170.253.8:57982 Connection reset, restarting [0] Mar 2 17:09:46 openvpn 48841 107.170.253.8:57982 WARNING: Bad encapsulated packet length from peer (5635), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...] Mar 2 17:09:46 openvpn 48841 TCP connection established with [AF_INET]107.170.253.8:57982 Mar 2 17:09:46 openvpn 48841 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:46 openvpn 48841 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:46 openvpn 48841 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication Mar 2 17:09:46 openvpn 48841 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key Mar 2 17:09:37 openvpn 48841 MANAGEMENT: Client disconnected Mar 2 17:09:37 openvpn 48841 MANAGEMENT: CMD 'quit' Mar 2 17:09:37 openvpn 48841 MANAGEMENT: CMD 'status 2' Mar 2 17:09:37 openvpn 48841 MANAGEMENT: Client connected from /var/etc/openvpn/server4/sock Mar 2 17:09:37 openvpn 73327 MANAGEMENT: Client disconnected Mar 2 17:09:37 openvpn 73327 MANAGEMENT: CMD 'quit' Mar 2 17:09:36 openvpn 73327 MANAGEMENT: CMD 'status 2' Mar 2 17:09:36 openvpn 73327 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sock Mar 2 17:08:34 openvpn 48841 MANAGEMENT: Client disconnected Mar 2 17:08:34 openvpn 48841 MANAGEMENT: CMD 'quit' Mar 2 17:08:34 openvpn 48841 MANAGEMENT: CMD 'status 2' Mar 2 17:08:34 openvpn 48841 MANAGEMENT: Client connected from /var/etc/openvpn/server4/sock Mar 2 17:08:34 openvpn 73327 MANAGEMENT: Client disconnected Mar 2 17:08:34 openvpn 73327 MANAGEMENT: CMD 'quit' Mar 2 17:08:34 openvpn 73327 MANAGEMENT: CMD 'status 2' Mar 2 17:08:33 openvpn 73327 MANAGEMENT: Client connected from /var/etc/openvpn/server3/sock Mar 2 17:07:31 openvpn 48841 MANAGEMENT: Client disconnectedNot sure if that gives any clue.
I was able to restart the VPN from the GUI, and it stayed up just fine. That tells me that there is something very different about the pfSense Auto restart and the GUI restart.
I think my little bash script that uses
pfSsh.php playback svc restart openvpn, and AFAIK it was successful in solving this issue (when the WAN doesn't screw up too badly. This has been an issue for me for at least 5 years, and when I put in the watchdog script, it seemed to go away.P.S: Is there any other way than
pfSsh.php playback gatewaystatusto get the status in a more machine readable form that would be easier to work with in a bash script.?Mar 2 06:15:00 php 80917 [pfBlockerNG] Starting cron process. Mar 2 06:16:30 php 80917 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 07:15:00 php 97642 [pfBlockerNG] Starting cron process. Mar 2 07:16:00 sshguard 90642 Exiting on signal. Mar 2 07:16:00 sshguard 75986 Now monitoring attacks. Mar 2 07:16:50 php 97642 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 08:15:00 php 1249 [pfBlockerNG] Starting cron process. Mar 2 08:17:02 php 1249 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 09:15:00 php 12121 [pfBlockerNG] Starting cron process. Mar 2 09:17:04 php 12121 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 10:15:00 php 18697 [pfBlockerNG] Starting cron process. Mar 2 10:17:06 php 18697 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 11:15:00 php 85155 [pfBlockerNG] Starting cron process. Mar 2 11:16:40 php 85155 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 12:15:00 php 91791 [pfBlockerNG] Starting cron process. Mar 2 12:17:17 php 91791 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 12:30:00 php 86652 rc.update_urltables: /etc/rc.update_urltables: Starting up. Mar 2 12:30:00 php 86652 rc.update_urltables: /etc/rc.update_urltables: Sleeping for 33 seconds. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: Starting URL table alias updates Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_MALIP1HR_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_MALIP6HR_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_BBC177IP_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_ULTIMATE_IP_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI1_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI5_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI3_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI2_v4 does not need updating. Mar 2 12:30:33 php 86652 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI4_v4 does not need updating. Mar 2 13:08:00 sshguard 75986 Exiting on signal. Mar 2 13:08:00 sshguard 49929 Now monitoring attacks. Mar 2 13:15:00 php 62501 [pfBlockerNG] Starting cron process. Mar 2 13:16:58 php 62501 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 14:15:00 php 14690 [pfBlockerNG] Starting cron process. Mar 2 14:16:56 php 14690 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 14:46:14 rc.gateway_alarm 5241 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:593.648ms RTTsd:1382.451ms Loss:0%) Mar 2 14:46:14 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 14:46:14 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:14 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:14 check_reload_status 396 Reloading filter Mar 2 14:46:14 rc.gateway_alarm 7363 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:644.890ms RTTsd:1423.938ms Loss:0%) Mar 2 14:46:14 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 14:46:14 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:14 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:14 check_reload_status 396 Reloading filter Mar 2 14:46:15 php-fpm 17557 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:15 php-fpm 17557 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 14:46:15 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:15 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 14:46:45 rc.gateway_alarm 48094 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:371.699ms RTTsd:1075.358ms Loss:0%) Mar 2 14:46:45 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 14:46:45 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:45 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:45 check_reload_status 396 Reloading filter Mar 2 14:46:45 rc.gateway_alarm 49922 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:325.207ms RTTsd:1034.753ms Loss:0%) Mar 2 14:46:45 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 14:46:45 check_reload_status 396 Restarting IPsec tunnels Mar 2 14:46:45 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 14:46:45 check_reload_status 396 Reloading filter Mar 2 14:46:46 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:46 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 14:46:46 php-fpm 91128 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 14:46:46 php-fpm 91128 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:15:00 php 54242 [pfBlockerNG] Starting cron process. Mar 2 15:16:34 php 54242 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 15:41:07 rc.gateway_alarm 26554 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:895.323ms RTTsd:2288.898ms Loss:0%) Mar 2 15:41:07 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:41:07 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:41:07 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:41:07 check_reload_status 396 Reloading filter Mar 2 15:41:07 rc.gateway_alarm 28826 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:829.265ms RTTsd:2134.126ms Loss:0%) Mar 2 15:41:07 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:41:07 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:41:07 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:41:07 check_reload_status 396 Reloading filter Mar 2 15:41:08 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:41:08 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:41:08 php-fpm 91128 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:41:08 php-fpm 91128 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:42:10 rc.gateway_alarm 19063 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:34.543ms RTTsd:101.709ms Loss:0%) Mar 2 15:42:10 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:42:10 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:42:10 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:42:10 check_reload_status 396 Reloading filter Mar 2 15:42:10 rc.gateway_alarm 20991 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:50.193ms RTTsd:102.034ms Loss:0%) Mar 2 15:42:10 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:42:10 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:42:10 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:42:10 check_reload_status 396 Reloading filter Mar 2 15:42:11 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:42:11 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:42:11 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:42:11 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:48:40 rc.gateway_alarm 63161 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:688.657ms RTTsd:1888.751ms Loss:0%) Mar 2 15:48:41 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:48:41 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:48:41 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:48:41 check_reload_status 396 Reloading filter Mar 2 15:48:41 rc.gateway_alarm 65610 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:689.002ms RTTsd:1853.070ms Loss:0%) Mar 2 15:48:41 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:48:41 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:48:41 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:48:41 check_reload_status 396 Reloading filter Mar 2 15:48:42 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:48:42 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:48:42 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:48:42 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:49:45 rc.gateway_alarm 58088 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:29.572ms RTTsd:100.481ms Loss:0%) Mar 2 15:49:45 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:49:45 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:49:45 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:49:45 check_reload_status 396 Reloading filter Mar 2 15:49:46 rc.gateway_alarm 60336 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:52.651ms RTTsd:111.949ms Loss:0%) Mar 2 15:49:46 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:49:46 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:49:46 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:49:46 check_reload_status 396 Reloading filter Mar 2 15:49:46 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:49:46 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:49:47 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:49:47 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:53:43 rc.gateway_alarm 61390 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:958.099ms RTTsd:2407.596ms Loss:0%) Mar 2 15:53:43 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:53:43 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:53:43 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:53:43 check_reload_status 396 Reloading filter Mar 2 15:53:43 rc.gateway_alarm 63840 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:984.444ms RTTsd:2424.976ms Loss:0%) Mar 2 15:53:43 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:53:43 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:53:43 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:53:43 check_reload_status 396 Reloading filter Mar 2 15:53:44 php-fpm 17557 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:53:44 php-fpm 17557 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:53:44 php-fpm 22688 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:53:44 php-fpm 22688 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 15:54:47 rc.gateway_alarm 53929 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:34.745ms RTTsd:113.154ms Loss:0%) Mar 2 15:54:47 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 15:54:47 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:54:47 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:54:47 check_reload_status 396 Reloading filter Mar 2 15:54:47 rc.gateway_alarm 57000 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:0 RTT:52.041ms RTTsd:113.582ms Loss:0%) Mar 2 15:54:47 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 15:54:47 check_reload_status 396 Restarting IPsec tunnels Mar 2 15:54:47 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 15:54:47 check_reload_status 396 Reloading filter Mar 2 15:54:48 php-fpm 17557 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:54:48 php-fpm 17557 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 15:54:48 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 15:54:48 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:15:00 php 96721 [pfBlockerNG] Starting cron process. Mar 2 16:16:44 php 96721 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload Mar 2 16:19:49 rc.gateway_alarm 60859 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:1 RTT:1012.870ms RTTsd:2509.895ms Loss:0%) Mar 2 16:19:49 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 16:19:49 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:19:49 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:19:49 check_reload_status 396 Reloading filter Mar 2 16:19:49 rc.gateway_alarm 63012 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:1089.423ms RTTsd:2611.882ms Loss:0%) Mar 2 16:19:49 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 16:19:49 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:19:49 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:19:49 check_reload_status 396 Reloading filter Mar 2 16:19:50 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:19:50 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:19:50 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:19:50 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 16:20:05 rc.gateway_alarm 92576 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:1413.616ms RTTsd:2911.066ms Loss:22%) Mar 2 16:20:05 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 16:20:05 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:20:05 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:20:05 check_reload_status 396 Reloading filter Mar 2 16:20:06 php-fpm 74959 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:20:06 php-fpm 74959 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:20:54 rc.gateway_alarm 19106 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:41.868ms RTTsd:133.746ms Loss:0%) Mar 2 16:20:54 check_reload_status 396 updating dyndns WAN_DHCP Mar 2 16:20:54 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:20:54 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:20:54 check_reload_status 396 Reloading filter Mar 2 16:20:55 php-fpm 76071 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:20:55 php-fpm 76071 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP. Mar 2 16:21:01 rc.gateway_alarm 79201 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%) Mar 2 16:21:01 check_reload_status 396 updating dyndns VPN_UDP_TOS_VPNV4 Mar 2 16:21:01 check_reload_status 396 Restarting IPsec tunnels Mar 2 16:21:01 check_reload_status 396 Restarting OpenVPN tunnels/interfaces Mar 2 16:21:01 check_reload_status 396 Reloading filter Mar 2 16:21:02 php-fpm 38038 /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 16:21:02 php-fpm 38038 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use VPN_UDP_TOS_VPNV4. Mar 2 16:50:57 root 55932 rc.update_bogons.sh is beginning the update cycle. Mar 2 16:51:03 root 62791 Bogons V4 file downloaded: 14 addresses added. Mar 2 16:51:03 root 62791 Bogons V4 file downloaded: 6 addresses deleted. Mar 2 16:51:03 root 65183 Bogons V6 file downloaded: 45 addresses added. Mar 2 16:51:03 root 65183 Bogons V6 file downloaded: 13 addresses deleted. Mar 2 16:51:03 root 65617 rc.update_bogons.sh is ending the update cycle. Mar 2 17:11:29 php-fpm 4753 /index.php: Successful login for user 'Barry_secure' from: 172.16.50.16 (Local Database) Mar 2 17:13:15 php-fpm 74959 OpenVPN terminate old pid: 70501 Mar 2 17:13:15 kernel ovpnc1: link state changed to DOWN Mar 2 17:13:15 check_reload_status 396 Reloading filter Mar 2 17:13:15 php-fpm 74959 OpenVPN PID written: 23195 Mar 2 17:13:15 check_reload_status 396 Reloading filter Mar 2 17:13:15 kernel ovpnc1: link state changed to UP Mar 2 17:13:15 check_reload_status 396 rc.newwanip starting ovpnc1 Mar 2 17:13:16 php-fpm 91128 /rc.newwanip: rc.newwanip: Info: starting on ovpnc1. Mar 2 17:13:16 php-fpm 91128 /rc.newwanip: rc.newwanip: on (IP address: 10.8.110.23) (interface: VPN_UDP_TOS[opt28]) (real interface: ovpnc1). Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 99.ZZZ.ZZZ.1 Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: Removing static route for monitor 8.8.4.4 and adding a new route through 10.8.110.23 Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. '' Mar 2 17:13:34 php-fpm 91128 /rc.newwanip: IP Address has changed, killing states on former IP Address 10.16.110.16. Mar 2 17:13:41 php-fpm 91128 /rc.newwanip: The command '/usr/sbin/arp -s '172.16.50.1' '00:xx:xx:xx:xx:05'' returned exit code '1', the output was 'arp: writing to routing socket: Operation not permitted' Mar 2 17:13:42 php-fpm 91128 /rc.newwanip: Creating rrd update script Mar 2 17:13:44 php-fpm 91128 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.16.110.16 -> 10.8.110.23 - Restarting packages. Mar 2 17:13:44 check_reload_status 396 Starting packages Mar 2 17:13:45 php-fpm 74959 /rc.start_packages: Restarting/Starting all packages. Mar 2 17:13:45 php-fpm 74959 /rc.start_packages: Reloading syslog-ng for configuration sync Mar 2 17:13:46 supervise/syslog-ng 43274 Daemon exited gracefully, not restarting; exitcode='0' Mar 2 17:13:50 php-fpm 74959 /rc.start_packages: The command '/usr/local/etc/rc.d/syslog-ng.sh stop' returned exit code '1', the output was '' Mar 2 17:13:52 check_reload_status 396 Reloading filter -
Mmm, Ok so right at the end of that log is where you login and restart the VPN client?
The service watchdog doesn't run at any time because the OpenVPN client doesn't ever die. It just keeps trying to connect which is what it's supposed to do.
Your WAN get's marked down numerous times during the 11 hours shown in that log but you can see each time the WAN gateway comes back up and so does the VPN gateway. The pings times to the monitred IP go back down to <50ms:
Mar 2 16:20:54 rc.gateway_alarm 19106 >>> Gateway alarm: WAN_DHCP (Addr:8.8.8.8 Alarm:0 RTT:41.868ms RTTsd:133.746ms Loss:0%)Until the last time where it comes back up but it at 100% packet loss:
Mar 2 16:21:01 rc.gateway_alarm 79201 >>> Gateway alarm: VPN_UDP_TOS_VPNV4 (Addr:8.8.4.4 Alarm:1 RTT:0.000ms RTTsd:0.000ms Loss:100%)We don't have the OpenVPN logs for that time but I imagine they have been repeating since then so it would be that 'Bad encapsulated packet length from peer' error followed by 'Connection reset, restarting [0]'.
Is that OpenVPN client connecting to the same remote address every time or a pool or remote addresses?
It's probably trying to connect to something that isn't an OpenVPN server. It's a TCP connection, what's the remote port?
