pfSense not responding to network after ISP outage
-
My ISP had an outage last night, one of their gateways stopped accepting PPPoE connections and it looks like I got impacted by it.
This morning I have no internet, pfSense web UI not loading and not responding to pings on it's LAN interface. I plugged a serial cable in and the system was at least alive. It could ping itself on it's LAN IP, but couldn't ping anything with a static IP on my LAN, nor anything on the internet. Had a look through /var/log/system.log and there's a lot of PPPoE reconnection attempts through the night, which is my first clue to check my ISP status page and discovered about one of their gateways. But also during the night, PPPoE seems to come back up and according to the logs the system seems happy.
What's odd though is why then I discover this morning it's not passing traffic. After not managing to get very far working out what went wrong I initiated a reboot over serial, it made the shutdown beep and logged a couple of messages to the console but then nothing more happened and it didn't reboot. Had to hard power cycle it.
I'd like to work out what went wrong, but not entirely sure where to start, pointers would be much appreciated please.
As a starting point, this is the last part of /var/log/system.log from when it looks like the PPPoE connection comes back up until I attempt to reboot and eventually power cycle it. IPs removed.
Oct 23 02:52:48 fw ppp[16230]: [wan_link0] LCP: LayerUp Oct 23 02:52:48 fw ppp[16230]: [wan_link0] CHAP: rec'd CHALLENGE #2 len: 29 Oct 23 02:52:48 fw ppp[16230]: [wan_link0] Name: "AAA" Oct 23 02:52:48 fw ppp[16230]: [wan_link0] CHAP: Using authname "AAA" Oct 23 02:52:48 fw ppp[16230]: [wan_link0] CHAP: sending RESPONSE #2 len: 38 Oct 23 02:52:48 fw ppp[16230]: [wan_link0] CHAP: rec'd SUCCESS #2 len: 4 Oct 23 02:52:48 fw ppp[16230]: [wan_link0] LCP: authorization successful Oct 23 02:52:48 fw ppp[16230]: [wan_link0] Link: Matched action 'bundle "wan" ""' Oct 23 02:52:48 fw ppp[16230]: [wan_link0] Link: Join bundle "wan" Oct 23 02:52:48 fw ppp[16230]: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: Open event Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: state change Initial --> Starting Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: LayerStart Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: Open event Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: state change Initial --> Starting Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: LayerStart Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: Up event Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: state change Starting --> Req-Sent Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: SendConfigReq #17 Oct 23 02:52:48 fw ppp[16230]: [wan] IPADDR 0.0.0.0 Oct 23 02:52:48 fw ppp[16230]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: Up event Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: state change Starting --> Req-Sent Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: SendConfigReq #9 Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: rec'd Configure Request #1 (Req-Sent) Oct 23 02:52:48 fw ppp[16230]: [wan] IPADDR XGWIPX Oct 23 02:52:48 fw ppp[16230]: [wan] XGWIPX is OK Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: SendConfigAck #1 Oct 23 02:52:48 fw ppp[16230]: [wan] IPADDR XGWIPX Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: state change Req-Sent --> Ack-Sent Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: rec'd Configure Request #1 (Req-Sent) Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: SendConfigAck #1 Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: state change Req-Sent --> Ack-Sent Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: rec'd Configure Reject #17 (Ack-Sent) Oct 23 02:52:48 fw ppp[16230]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Oct 23 02:52:48 fw ppp[16230]: [wan] IPCP: SendConfigReq #18 Oct 23 02:52:48 fw ppp[16230]: [wan] IPADDR 0.0.0.0 Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: rec'd Configure Ack #9 (Ack-Sent) Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: state change Ack-Sent --> Opened Oct 23 02:52:48 fw ppp[16230]: [wan] IPV6CP: LayerUp Oct 23 02:52:48 fw ppp[16230]: [wan] XV6X -> XV6X Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw kernel: ng_pppoe[14]: no matching session Oct 23 02:52:49 fw php[53482]: /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0 Oct 23 02:52:49 fw php[53482]: /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode Oct 23 02:52:49 fw php[53482]: /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0) Oct 23 02:52:51 fw check_reload_status[430]: rc.newwanipv6 starting pppoe0 Oct 23 02:52:51 fw ppp[16230]: [wan] IFACE: Up event Oct 23 02:52:51 fw ppp[16230]: [wan] IFACE: Rename interface ng0 to pppoe0 Oct 23 02:52:51 fw ppp[16230]: [wan] IFACE: Add description "WAN" Oct 23 02:52:51 fw ppp[16230]: [wan] IPCP: rec'd Configure Nak #18 (Ack-Sent) Oct 23 02:52:51 fw ppp[16230]: [wan] IPADDR XWANIPX Oct 23 02:52:51 fw ppp[16230]: [wan] XWANIPX is OK Oct 23 02:52:51 fw ppp[16230]: [wan] IPCP: SendConfigReq #19 Oct 23 02:52:51 fw ppp[16230]: [wan] IPADDR XWANIPX Oct 23 02:52:51 fw ppp[16230]: [wan] IPCP: rec'd Configure Ack #19 (Ack-Sent) Oct 23 02:52:51 fw ppp[16230]: [wan] IPADDR XWANIPX Oct 23 02:52:51 fw ppp[16230]: [wan] IPCP: state change Ack-Sent --> Opened Oct 23 02:52:51 fw ppp[16230]: [wan] IPCP: LayerUp Oct 23 02:52:51 fw ppp[16230]: [wan] XWANIPX -> XGWIPX Oct 23 02:52:51 fw check_reload_status[430]: rc.newwanip starting pppoe0 Oct 23 02:52:52 fw php-fpm[68321]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Oct 23 02:52:52 fw php-fpm[68321]: /rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan]. Oct 23 02:52:52 fw php-fpm[68321]: /rc.newwanip: rc.newwanip: Info: starting on pppoe0. Oct 23 02:52:52 fw php-fpm[68321]: /rc.newwanip: rc.newwanip: on (IP address: XWANIPX) (interface: WAN[wan]) (real interface: pppoe0). Oct 23 02:52:59 fw php-fpm[68321]: /rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default. Oct 23 02:53:00 fw sshguard[73849]: Exiting on signal. Oct 23 02:53:00 fw sshguard[26899]: Now monitoring attacks. Oct 23 02:53:00 fw rtsold[31644]: Received RA specifying route XV6X for interface wan(pppoe0) Oct 23 02:53:00 fw rtsold[32795]: RTSOLD Lock in place - sending SIGHUP to dhcp6c Oct 23 02:53:00 fw php-fpm[68321]: /rc.newwanip: Forcefully reloading IPsec Oct 23 02:53:00 fw check_reload_status[430]: Reloading filter Oct 23 02:53:01 fw php-fpm[398]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Oct 23 02:53:01 fw php-fpm[398]: /rc.newwanipv6: rc.newwanipv6: on (IP address: XV6X) (interface: wan) (real interface: pppoe0). Oct 23 02:53:01 fw php-fpm[68321]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Oct 23 02:53:02 fw php-fpm[68321]: OpenVPN terminate old pid: 68625 Oct 23 02:53:04 fw kernel: ovpns1: link state changed to DOWN Oct 23 02:53:04 fw check_reload_status[430]: Reloading filter Oct 23 02:53:05 fw check_reload_status[430]: Reloading filter Oct 23 02:53:05 fw php-fpm[398]: /rc.newwanipv6: Ignoring IPsec reload since there are no tunnels on interface wan Oct 23 02:53:05 fw php-fpm[398]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Oct 23 02:53:05 fw php-fpm[398]: /rc.newwanipv6: Creating rrd update script Oct 23 02:53:05 fw php-fpm[68321]: OpenVPN PID written: 91961 Oct 23 02:53:05 fw php-fpm[398]: /rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - -> XV6X - Restarting packages. Oct 23 02:53:05 fw kernel: ovpns1: link state changed to UP Oct 23 02:53:05 fw check_reload_status[430]: Starting packages Oct 23 02:53:05 fw php-fpm[68321]: /rc.newwanip: Creating rrd update script Oct 23 02:53:05 fw check_reload_status[430]: rc.newwanip starting ovpns1 Oct 23 02:53:06 fw php-fpm[399]: /rc.start_packages: Restarting/Starting all packages. Oct 23 02:53:06 fw php-fpm[92649]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1. Oct 23 02:53:06 fw php-fpm[92649]: /rc.newwanip: rc.newwanip: on (IP address: 10.6.100.1) (interface: []) (real interface: ovpns1). Oct 23 02:53:06 fw php-fpm[92649]: /rc.newwanip: rc.newwanip called with empty interface. Oct 23 02:53:06 fw php-fpm[92649]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 10.6.100.1 - Restarting packages. Oct 23 02:53:06 fw check_reload_status[430]: Starting packages Oct 23 02:53:07 fw php-fpm[68321]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - XWANIPX -> XWANIPX - Restarting packages. Oct 23 02:53:07 fw check_reload_status[430]: Starting packages Oct 23 02:53:07 fw php-fpm[92649]: /rc.start_packages: Restarting/Starting all packages. Oct 23 02:53:08 fw php-fpm[399]: /rc.start_packages: Restarting/Starting all packages. Oct 23 02:59:00 fw sshguard[26899]: Exiting on signal. Oct 23 02:59:00 fw sshguard[87972]: Now monitoring attacks. Oct 23 03:28:00 fw sshguard[87972]: Exiting on signal. Oct 23 03:28:00 fw sshguard[1055]: Now monitoring attacks. Oct 23 03:35:00 fw sshguard[1055]: Exiting on signal. Oct 23 03:35:00 fw sshguard[18095]: Now monitoring attacks. Oct 23 03:56:00 fw sshguard[18095]: Exiting on signal. Oct 23 03:56:00 fw sshguard[40983]: Now monitoring attacks. Oct 23 04:09:00 fw sshguard[40983]: Exiting on signal. Oct 23 04:09:00 fw sshguard[15970]: Now monitoring attacks. Oct 23 04:21:00 fw sshguard[15970]: Exiting on signal. Oct 23 04:21:00 fw sshguard[18277]: Now monitoring attacks. Oct 23 04:25:00 fw sshguard[18277]: Exiting on signal. Oct 23 04:25:00 fw sshguard[61886]: Now monitoring attacks. Oct 23 04:54:00 fw sshguard[61886]: Exiting on signal. Oct 23 04:54:00 fw sshguard[71579]: Now monitoring attacks. Oct 23 05:07:00 fw sshguard[71579]: Exiting on signal. Oct 23 05:07:00 fw sshguard[9209]: Now monitoring attacks. Oct 23 05:23:00 fw sshguard[9209]: Exiting on signal. Oct 23 05:23:00 fw sshguard[60578]: Now monitoring attacks. Oct 23 05:52:00 fw sshguard[60578]: Exiting on signal. Oct 23 05:52:00 fw sshguard[76264]: Now monitoring attacks. Oct 23 05:53:00 fw sshguard[76264]: Exiting on signal. Oct 23 05:53:00 fw sshguard[14063]: Now monitoring attacks. Oct 23 06:21:00 fw sshguard[14063]: Exiting on signal. Oct 23 06:21:00 fw sshguard[52376]: Now monitoring attacks. Oct 23 06:39:00 fw sshguard[52376]: Exiting on signal. Oct 23 06:39:00 fw sshguard[68754]: Now monitoring attacks. Oct 23 06:51:00 fw sshguard[68754]: Exiting on signal. Oct 23 06:51:00 fw sshguard[98477]: Now monitoring attacks. Oct 23 07:25:00 fw sshguard[98477]: Exiting on signal. Oct 23 07:25:00 fw sshguard[51561]: Now monitoring attacks. Oct 23 08:01:00 fw sshguard[51561]: Exiting on signal. Oct 23 08:01:00 fw sshguard[11229]: Now monitoring attacks. Oct 23 08:08:00 fw sshguard[11229]: Exiting on signal. Oct 23 08:08:00 fw sshguard[32945]: Now monitoring attacks. Oct 23 08:11:00 fw sshguard[32945]: Exiting on signal. Oct 23 08:11:00 fw sshguard[43107]: Now monitoring attacks. Oct 23 08:21:39 fw login[97847]: login on ttyu0 as root Oct 23 08:21:46 fw login[2606]: login on ttyu0 as root Oct 23 08:21:55 fw login[3768]: login on ttyu0 as root Oct 23 08:22:30 fw login[40698]: login on ttyu0 as root Oct 23 08:25:00 fw sshguard[43107]: Exiting on signal. Oct 23 08:25:00 fw sshguard[43462]: Now monitoring attacks. Oct 23 08:34:03 fw php-cgi[75812]: rc.initial.reboot: Stopping all packages. Oct 23 08:34:06 fw reboot[83072]: rebooted by root Oct 23 08:34:06 fw syslogd: exiting on signal 15 Oct 23 08:37:34 fw syslogd: kernel boot file is /boot/kernel/kernel Oct 23 08:37:34 fw kernel: ---<<BOOT>>---
-
@jamie said in pfSense not responding to network after ISP outage:
beep and logged a couple of messages to the console but then nothing more happened and it didn't reboot.
That part, on the console access, from initial power up, going trough initial drive detection, and booting from a selected boot drive, and eventually booting pfSense, holds the info about what is happening.
Can you show it ? -
Did it come up with an IP or gateway that conflicted with any other locally defined subnet? You have obscured the IPs so we can't check.
-
@Gertjan please correct me if I'm wrong but are you saying that the log of the next boot contains information on why the shutdown prior failed? I would think that is unlikely.
@stephenw10 I've only obscured the WAN and upstream gateway IPs, both of which I've just done a find and replace on so anywhere you see
XWANX
, this is referencing a single IP address, same forXGWX
. My WAN IP is static and was not one of my local subnets (which are all 10.x.x.x). Equally my gateway IP was correctly my ISP's gateway (another public address). -
@jamie said in pfSense not responding to network after ISP outage:
Equally my gateway IP was correctly my ISP's gateway (another public address).
Ok. I asked because ISPs using PPPoE commonly use a private IP address for the upstream gateway and that cannot conflict
-
Ah ok. Mine is a public address, I looked it up and confirmed it's in a range owned by my ISP.
-
Hmm, what NICs are you using? On LAN especially? Hard to see anything that would prevent it pinging out from the LAN as long as LAN clients still had a valid IP address.
-
Here I'm using a PC Engines APU2 system with 3x onboard Intel I210 gigabit NICs. Some LAN clients still had their DHCP addresses, others were failing to DHCP as it wasn't getting served. Equally I tried pinging something with a known static IP and nothing.
-
Hmm, shouldn't be an issue with the NICs on that. Unless it's actually a hardware problem.
I'd try something low level. Start a continuous ping from the command line to something static on the LAN. Run a packet capture on the LAN interface to make sure it's actually sending packets.
-
@jamie said in pfSense not responding to network after ISP outage:
please correct me if I'm wrong but are you saying that the log of the next boot contains information on why the shutdown prior failed? I would think that is unlikely.
Correct.
But I was asking for this :@jamie said in pfSense not responding to network after ISP outage:
nothing more happened and it didn't reboot.
For this
@jamie said in pfSense not responding to network after ISP outage:
... contains information on why the shutdown prior failed?
For this the logs before the failed shutdown can show usefull info.
-
@stephenw10 I had to force reboot at the time to get back online so unfortunately can't try now but if it happens again I'll run a capture and check that. Thanks!
@Gertjan I have provided the system.log covering the duration from when I initiated a reboot to the first two lines of the next boot after I had to pull power as the system appeared to have gotten stuck. Is there a different log file which you're interested to see?