pfSense

Hi,

I previously logged bug #4992 but then retracted it as I worked further on the problem. It now turns out that I have a problem with having more than 1 WAN connection up following the upgrade to 2.2.4

As per this Reddit post: https://www.reddit.com/r/PFSENSE/comments/3idccv/gateway_down_after_213_224_upgrade/ it appears that I cannot get more than one PPPoE-based WAN connection up at any one time. I can have one or the other, but not both, and it appears to be fairly random as to which connection I get, despite both connections being perfectly fine prior to the upgrade and also perfectly fine when tested against a BT Business Hub router independently.

Pic attached showing the dashboard following the last reboot, with PPPoE-negotiated WAN IPs and the apinger showing WAN2 as being down.

Current logs are:

General log entries
Aug 26 17:07:33 php-fpm²⁵⁹⁷⁷: /rc.newwanip: rc.newwanip: on (IP address: 192.168.191.2) (interface: []) (real interface: ovpnc2).
Aug 26 17:07:33 check_reload_status: Reloading filter
Aug 26 17:07:33 php-fpm²⁵⁹⁷⁷: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 192.168.191.2 - Restarting packages.
Aug 26 17:07:33 php-fpm²⁵⁹⁷⁷: /rc.newwanip: rc.newwanip: Info: starting on ovpnc4.
Aug 26 17:07:33 php-fpm²⁵⁹⁷⁷: /rc.newwanip: rc.newwanip: on (IP address: 192.168.189.2) (interface: []) (real interface: ovpnc4).
Aug 26 17:07:33 php-fpm²⁵⁹⁷⁷: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 192.168.189.2 - Restarting packages.
Aug 26 17:07:33 php-fpm²⁵⁹⁷⁷: /rc.start_packages: Restarting/Starting all packages.
Aug 26 17:07:33 php-fpm²⁵⁹⁷⁷: /rc.start_packages: Restarting/Starting all packages.
Aug 26 17:07:34 php-fpm⁹⁵³³⁰: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 86.149.121.170 -> 86.147.247.114 - Restarting packages.
Aug 26 17:07:34 snmpd⁶⁵²³¹: disk_OS_get_disks: adding device 'da0' to device list
Aug 26 17:07:34 check_reload_status: Starting packages
Aug 26 17:07:34 snmpd⁶⁵²³¹: disk_OS_get_disks: adding device 'cd0' to device list
Aug 26 17:07:35 php-fpm⁹⁵³³⁰: /rc.start_packages: Restarting/Starting all packages.
Aug 26 17:07:36 check_reload_status: Restarting ipsec tunnels
Aug 26 17:07:38 check_reload_status: updating dyndns opt1
Aug 26 17:07:40 snmpd⁷⁶⁵²⁵: disk_OS_get_disks: adding device 'da0' to device list
Aug 26 17:07:40 snmpd⁷⁶⁵²⁵: disk_OS_get_disks: adding device 'cd0' to device list
Aug 26 17:07:40 check_reload_status: Reloading filter
Aug 26 17:07:40 php-fpm⁹²⁸²⁶: /interfaces.php: Creating rrd update script
Aug 26 17:07:41 php-fpm²⁵⁹⁷⁷: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN1First
Aug 26 17:07:41 php-fpm²⁵⁹⁷⁷: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN2First
Aug 26 17:07:41 php-fpm²⁵⁹⁷⁷: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WANBalanced
Aug 26 17:07:50 check_reload_status: updating dyndns WAN2_PPPOE
Aug 26 17:07:50 check_reload_status: Restarting ipsec tunnels
Aug 26 17:07:50 check_reload_status: Restarting OpenVPN tunnels/interfaces
Aug 26 17:07:50 check_reload_status: Reloading filter
Aug 26 17:07:51 php-fpm²⁴⁴⁷¹: /rc.dyndns.update: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN1First
Aug 26 17:07:51 php-fpm²⁴⁴⁷¹: /rc.dyndns.update: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN2First
Aug 26 17:07:51 php-fpm²⁴⁴⁷¹: /rc.dyndns.update: MONITOR: WAN2_PPPOE is down, omitting from routing group WANBalanced
Aug 26 17:07:51 php-fpm²⁴⁴⁷¹: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN2_PPPOE.
Aug 26 17:07:51 php-fpm²⁴⁴⁷¹: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN1First
Aug 26 17:07:51 php-fpm²⁴⁴⁷¹: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN2First
Aug 26 17:07:51 php-fpm²⁴⁴⁷¹: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WANBalanced
Aug 26 17:09:36 check_reload_status: Syncing firewall
Aug 26 17:09:38 php-fpm⁹⁷⁹⁹⁰: /system_gateways.php: ROUTING: setting default route to 81.134.160.1
Aug 26 17:09:38 check_reload_status: Reloading filter
Aug 26 17:11:24 check_reload_status: Syncing firewall
Aug 26 17:11:26 php-fpm⁷⁷⁹⁴⁹: /system_gateways.php: ROUTING: setting default route to 81.134.160.1
Aug 26 17:11:26 check_reload_status: Reloading filter
Aug 26 17:11:46 check_reload_status: updating dyndns WAN2_PPPOE
Aug 26 17:11:46 check_reload_status: Restarting ipsec tunnels
Aug 26 17:11:46 check_reload_status: Restarting OpenVPN tunnels/interfaces
Aug 26 17:11:46 check_reload_status: Reloading filter
Aug 26 17:11:47 php-fpm¹⁷⁴⁸¹: /rc.dyndns.update: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN1First
Aug 26 17:11:47 php-fpm¹⁷⁴⁸¹: /rc.dyndns.update: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN2First
Aug 26 17:11:47 php-fpm¹⁷⁴⁸¹: /rc.dyndns.update: MONITOR: WAN2_PPPOE is down, omitting from routing group WANBalanced
Aug 26 17:11:47 php-fpm¹⁷⁴⁸¹: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN2_PPPOE.
Aug 26 17:11:47 php-fpm¹⁷⁴⁸¹: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN1First
Aug 26 17:11:47 php-fpm¹⁷⁴⁸¹: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WAN2First
Aug 26 17:11:47 php-fpm¹⁷⁴⁸¹: /rc.filter_configure_sync: MONITOR: WAN2_PPPOE is down, omitting from routing group WANBalanced

Gateway log entries
Aug 25 12:42:42 apinger: SIGHUP received, reloading configuration.
Aug 25 12:50:43 apinger: SIGHUP received, reloading configuration.
Aug 25 12:50:54 apinger: ALARM: WAN_PPPOE(172.16.12.35) * down
Aug 25 18:39:59 apinger: ALARM: WAN2_PPPOE(81.148.96.1) down
Aug 25 18:39:59 apinger: alarm canceled: WAN2_PPPOE(81.148.96.1) down
Aug 26 01:30:37 apinger: ALARM: WAN2_PPPOE(81.148.96.1) down
Aug 26 01:31:10 apinger: alarm canceled: WAN2_PPPOE(81.148.96.1) down
Aug 26 01:31:20 apinger: ALARM: WAN2_PPPOE(81.148.96.1) delay
Aug 26 01:31:22 apinger: alarm canceled: WAN2_PPPOE(81.148.96.1) delay
Aug 26 12:46:51 apinger: ALARM: WAN2_PPPOE(81.148.96.1) down
Aug 26 12:47:37 apinger: alarm canceled: WAN2_PPPOE(81.148.96.1) down
Aug 26 12:47:46 apinger: ALARM: WAN2_PPPOE(81.148.96.1) delay
Aug 26 12:47:48 apinger: alarm canceled: WAN2_PPPOE(81.148.96.1) delay
Aug 26 12:54:12 apinger: SIGHUP received, reloading configuration.
Aug 26 12:54:12 apinger: alarm canceled (config reload): WAN_PPPOE(172.16.12.35) down
Aug 26 12:54:23 apinger: ALARM: WAN_PPPOE(172.16.12.35) down
Aug 26 12:54:23 apinger: SIGHUP received, reloading configuration.
Aug 26 14:19:22 apinger: SIGHUP received, reloading configuration.
Aug 26 14:22:51 apinger: SIGHUP received, reloading configuration.
Aug 26 15:31:01 apinger: ALARM: WAN2_PPPOE(81.148.96.1) down
Aug 26 15:32:04 apinger: SIGHUP received, reloading configuration.
Aug 26 15:32:04 apinger: alarm canceled (config reload): WAN_PPPOE(172.16.12.35) down
Aug 26 15:32:04 apinger: alarm canceled (config reload): WAN2_PPPOE(81.148.96.1) down
Aug 26 15:32:14 apinger: ALARM: WAN2_PPPOE(172.16.12.35) down
Aug 26 15:37:06 apinger: Starting Alarm Pinger, apinger(25837)
Aug 26 15:39:23 apinger: ALARM: WAN_PPPOE(81.134.160.1) down
Aug 26 15:41:01 apinger: SIGHUP received, reloading configuration.
Aug 26 15:41:01 apinger: alarm canceled (config reload): WAN_PPPOE(81.134.160.1) down
Aug 26 15:41:01 apinger: alarm canceled (config reload): WAN2_PPPOE(172.16.12.35) down
Aug 26 15:41:11 apinger: ALARM: WAN2_PPPOE(172.16.12.35) down
Aug 26 15:42:22 apinger: SIGHUP received, reloading configuration.
Aug 26 15:43:13 apinger: ALARM: WAN_PPPOE(81.148.96.1) down
Aug 26 15:44:35 apinger: SIGHUP received, reloading configuration.
Aug 26 15:44:35 apinger: alarm canceled (config reload): WAN_PPPOE(81.148.96.1) down
Aug 26 15:44:35 apinger: alarm canceled (config reload): WAN2_PPPOE(172.16.12.35) down
Aug 26 15:44:46 apinger: ALARM: WAN2_PPPOE(172.16.12.35) down
Aug 26 15:45:54 apinger: SIGHUP received, reloading configuration.
Aug 26 16:33:37 apinger: ALARM: WAN_PPPOE(81.148.96.1) down
Aug 26 16:36:27 apinger: alarm canceled: WAN_PPPOE(81.148.96.1) down
Aug 26 16:36:29 apinger: SIGHUP received, reloading configuration.
Aug 26 17:02:12 apinger: Starting Alarm Pinger, apinger(25593)
Aug 26 17:06:42 apinger: ALARM: WAN2_PPPOE(172.16.12.35) down
Aug 26 17:07:29 apinger: SIGHUP received, reloading configuration.
Aug 26 17:07:29 apinger: alarm canceled (config reload): WAN2_PPPOE(172.16.12.35) down
Aug 26 17:07:40 apinger: ALARM: WAN2_PPPOE(172.16.12.35) down
Aug 26 17:07:40 apinger: SIGHUP received, reloading configuration.
Aug 26 17:09:38 apinger: SIGHUP received, reloading configuration.
Aug 26 17:09:38 apinger: alarm canceled (config reload): WAN2_PPPOE(172.16.12.35) down
Aug 26 17:11:26 apinger: SIGHUP received, reloading configuration.
Aug 26 17:11:36 apinger: ALARM: WAN2_PPPOE(172.16.12.35) down *

Routing daemon log entries
Aug 25 12:42:05 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 25 12:42:05 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 25 12:42:05 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 25 12:42:34 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 25 12:42:34 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 25 12:42:34 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 25 12:42:40 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 25 12:42:40 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 25 12:42:40 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 25 12:50:44 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 25 12:50:44 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 25 12:50:44 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 26 12:54:14 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 26 12:54:14 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 12:54:14 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 26 12:54:21 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 26 12:54:21 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 12:54:21 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 26 14:19:20 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 26 14:19:20 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 14:19:20 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 26 15:32:05 radvd³⁶⁸⁸⁰: attempting to reread config file
Aug 26 15:32:05 radvd³⁶⁸⁸⁰: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 15:32:05 radvd³⁶⁸⁸⁰: resuming normal operation
Aug 26 15:37:09 radvd³⁹⁰⁹⁸: version 1.9.1 started
Aug 26 15:37:09 radvd³⁹⁰⁹⁸: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 15:41:02 radvd³⁹⁵⁸²: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 15:41:02 radvd³⁹⁵⁸²: resuming normal operation
Aug 26 15:42:23 radvd³⁹⁵⁸²: attempting to reread config file
Aug 26 15:42:23 radvd³⁹⁵⁸²: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 15:42:23 radvd³⁹⁵⁸²: resuming normal operation
Aug 26 15:44:36 radvd³⁹⁵⁸²: attempting to reread config file
Aug 26 15:44:36 radvd³⁹⁵⁸²: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 15:44:36 radvd³⁹⁵⁸²: resuming normal operation
Aug 26 15:45:56 radvd³⁹⁵⁸²: attempting to reread config file
Aug 26 15:45:56 radvd³⁹⁵⁸²: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 15:45:56 radvd³⁹⁵⁸²: resuming normal operation
Aug 26 16:36:30 radvd³⁹⁵⁸²: attempting to reread config file
Aug 26 16:36:30 radvd³⁹⁵⁸²: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 16:36:30 radvd³⁹⁵⁸²: resuming normal operation
Aug 26 17:02:15 radvd³⁸³²⁴: version 1.9.1 started
Aug 26 17:02:15 radvd³⁸³²⁴: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 17:06:32 radvd³⁸⁴³⁶: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 17:06:32 radvd³⁸⁴³⁶: resuming normal operation
Aug 26 17:07:30 radvd³⁸⁴³⁶: attempting to reread config file
Aug 26 17:07:30 radvd³⁸⁴³⁶: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 17:07:30 radvd³⁸⁴³⁶: resuming normal operation
Aug 26 17:07:38 radvd³⁸⁴³⁶: attempting to reread config file
Aug 26 17:07:38 radvd³⁸⁴³⁶: no auto-selected prefix on interface em1, disabling advertisements
Aug 26 17:07:38 radvd³⁸⁴³⁶: resuming normal operation

Resolver log entries
Aug 26 16:36:29 dnsmasq³⁶⁷⁸¹: using nameserver 8.8.4.4#53
Aug 26 16:37:46 dnsmasq³⁶⁷⁸¹: reading /etc/resolv.conf
Aug 26 16:37:46 dnsmasq³⁶⁷⁸¹: ignoring nameserver 127.0.0.1 - local interface
Aug 26 16:37:46 dnsmasq³⁶⁷⁸¹: using nameserver 194.72.0.98#53
Aug 26 16:37:46 dnsmasq³⁶⁷⁸¹: using nameserver 194.74.65.68#53
Aug 26 16:37:46 dnsmasq³⁶⁷⁸¹: using nameserver 8.8.8.8#53
Aug 26 16:37:46 dnsmasq³⁶⁷⁸¹: using nameserver 8.8.4.4#53
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: started, version 2.73 cachesize 10000
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: compile time options: IPv6 GNU-getopt no-DBus i18n IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset auth DNSSEC loop-detect no-inotify
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: reading /etc/resolv.conf
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: ignoring nameserver 127.0.0.1 - local interface
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: using nameserver 194.74.65.69#53
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: using nameserver 194.72.0.114#53
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: using nameserver 8.8.8.8#53
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: using nameserver 8.8.4.4#53
Aug 26 17:02:15 dnsmasq³³⁹⁷⁸: read /etc/hosts - 3 addresses
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: reading /etc/resolv.conf
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: ignoring nameserver 127.0.0.1 - local interface
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: using nameserver 194.74.65.69#53
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: using nameserver 194.72.0.114#53
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: using nameserver 213.120.234.34#53
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: using nameserver 194.72.9.34#53
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: using nameserver 8.8.8.8#53
Aug 26 17:06:32 dnsmasq³³⁹⁷⁸: using nameserver 8.8.4.4#53
Aug 26 17:07:26 dnsmasq³³⁹⁷⁸: reading /etc/resolv.conf
Aug 26 17:07:26 dnsmasq³³⁹⁷⁸: ignoring nameserver 127.0.0.1 - local interface
Aug 26 17:07:26 dnsmasq³³⁹⁷⁸: using nameserver 194.74.65.69#53
Aug 26 17:07:26 dnsmasq³³⁹⁷⁸: using nameserver 194.72.0.114#53
Aug 26 17:07:26 dnsmasq³³⁹⁷⁸: using nameserver 8.8.8.8#53
Aug 26 17:07:26 dnsmasq³³⁹⁷⁸: using nameserver 8.8.4.4#53
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: reading /etc/resolv.conf
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: ignoring nameserver 127.0.0.1 - local interface
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: using nameserver 194.74.65.69#53
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: using nameserver 194.72.0.114#53
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: using nameserver 213.120.234.34#53
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: using nameserver 194.72.9.34#53
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: using nameserver 8.8.8.8#53
Aug 26 17:07:30 dnsmasq³³⁹⁷⁸: using nameserver 8.8.4.4#53
Aug 26 17:07:36 dnsmasq³³⁹⁷⁸: exiting on receipt of SIGTERM
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: started, version 2.73 cachesize 10000
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: compile time options: IPv6 GNU-getopt no-DBus i18n IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset auth DNSSEC loop-detect no-inotify
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: reading /etc/resolv.conf
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: ignoring nameserver 127.0.0.1 - local interface
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: using nameserver 194.74.65.69#53
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: using nameserver 194.72.0.114#53
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: using nameserver 213.120.234.34#53
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: using nameserver 194.72.9.34#53
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: using nameserver 8.8.8.8#53
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: using nameserver 8.8.4.4#53
Aug 26 17:07:37 dnsmasq⁷²²⁹⁸: read /etc/hosts - 3 addresses