pfSense unable to recover Internet access after power outage
-
I just had a power outage earlier today and after pfSense recovered, the WAN access didn't recover. After restarting the router with no luck, I went into interfaces/WAN (the interface that was down) and saved it again. This forced the DHCP client on that interface to make a new DHCP request and... It came up. With a new public IP address. Yes, I have my router configured as pass-thru, so that I have a public IP on the WAN interface.
Well, I imagine that this means that the power outage I suffered in my location, also affected the POC of my Network provider.
pfSense recovered from the outage @6:47. I was able to get the WAN interface going again @9:30. Because I am a Multi-WAN set-up, I didn't need to recover the 2nd WAN sooner, but it also tells me that this could be done better.
Is there a way, without manual intervention, to force the WAN interface to issue a new DHCP request, after the interface has been down for a while?
-
@fbrunken In my experience, issues like this are usually caused by the CPE gear from the ISP, for example Comcast's modems will stick to issuing a single IP over DHCP even after a power loss (sometimes, not all the time), so no matter what I do with pfSense, I have to physically unplug the modem and replug it's RJ45 to get a new DHCP lease to come through and sometimes need to reboot an additional time on the modem.
This isn't to say this is always the case, I have a number of pfSense setups with DHCP on the WAN side that come back up after power outages and DHCP lease renewals all the time and haven't really been able to pinpoint exactly what the cause is for this behavior.
How long did you wait after power came back to see if it would get a new lease?
-
@fbrunken
What's to see in the system and DHCP log regarding this?Some ISP change the responsible DHCP server after restoring the connection, however pfSense tries to use its valid lease.
-
Thanks for the feedback. Here is more information. Here is the timeline:
Begining: 06:47:13 Bootup complete
End: 09:30:31 MONITOR: WAN1_DHCP is available now, adding to routing group WANLoadBalancer 205.250.xxx.xx|205.250.150.xx|WAN1_DHCP|6.559ms|0.564ms|0.0%|online|none
This end was forced by me going into the interface and just saving it again. It forced pfSense to a DHCPREQUEST.My first reaction was to sit and wait. Around 9h, I don't have a timestamp, surely before 9:30h I did try a restart of the CPE. Again, I was not in a hurry because although WAN1 is a fiber connection from Telus, WAN2 is Startlink. When both are working I have a 2-1 load balance. So, 2 to Telus and one to Startlink.
Attached is the DHCP log. I masked the IPs that I don't believe to be important for troubleshooting. I had this problem before... I am in a remote location and power outages happen occasionally and I don't have UPS. I just don't have a test environment where I can test this situation, otherwise I would.
-
@fbrunken
pfSense is sending DHCP requests to a private server address:DHCPREQUEST on igc1 to 10.27.191.19 port 67
So I'm wondering, which IP is this?
Is it the local IP of the router?To avoid accepting leases from the local server, you can enter its IP into "Reject leases from" in the interface settings.
-
@viragomann said in pfSense unable to recover Internet access after power outage:
@fbrunken
pfSense is sending DHCP requests to a private server address:DHCPREQUEST on igc1 to 10.27.191.19 port 67
So I'm wondering, which IP is this?
Is it the local IP of the router?To avoid accepting leases from the local server, you can enter its IP into "Reject leases from" in the interface settings.
Good question. I saw this as well but since it goes on all the time, I decided to ignore it. Also, and as far as I can remember, the CPE does not work on this IP range... I will investigate the CPE more but the CPE for Telus is in another building, so I was lazy.
And in the meantime, I will reject leases from this IP.
-
Did you ever find a resolution to this ? This happens to me at every power outage. I use a Comcast XB8 in bridge mode and a custom PC running pfSense.
It happened once while I was at work. I came back home hours later to a fully powered home, but no Internet access.
I tried to automate this with Z-wave smartplugs and home assistant, to automatically cycle power for the modem and router respectively based on not being pingable for 30 minutes each. This failed because HAOS apparently requires internet access when booting up, and it couldn't get it. Getting a LAN IP is not sufficient for HAOS. Sigh. I think that is a regression.
Anyway, I'm wondering if there is any way to automatically recover when one is not physically present, for example on vacation, and there is no one to power cycle the modem and/or router. -
@madbrain in short. No.
I did however add "Reject leases from" a few IP addresses, as suggested above. Do I believe it will fix the problem? No. But I can not reproduce nor I had another outage again, similar to the last one when it last happened... So, I continue to monitor and hopefully, it will happen again and I will have more information on the problem.
If you had the problem, collect the logs. More logs may help identify the issue.
-
@fbrunken thanks. I'll try to reproduce it once more. My last outage was about 2 weeks ago. Maybe there is something in the logs already.
-
@madbrain Also, the IP address that I was asked about, I honestly don't know where it comes from but surely not from my ISP. The CPE operates on 192.168.1.xxx
And despite all my efforts, I just don't understand it. The message is:
DHCPREQUEST on igc1 to 10.27.191.19 port 67
It still going today, and as I understand, not an offer from the CPE but a request from pfSense. So, I don't see it as the issue but... Go figure. And to be sure, this IP range is not used on my LAN, so I can't see it being generated from the LAN side.
-
@madbrain I hope you can recreate it. I am thinking about starting my pfSense in a VM environment to test a few things... I may try this one as well.
-
@fbrunken I'm using PfSense on bare metal, on an AMD 5700g APU with an Intel 550 2-port 10 gig card.
It definitely boots faster than the modem can sync up. That may have something to do with it.
My HAOS is on a VM on a separate physical box, but I'm using free VMware and can only have one VM. -
@madbrain btw it's not just HAOS not getting internet access. The other 167 devices also fail.
-
@fbrunken
FYI, here are the entries from my "Gateways" tab on the day of my last outage. Times are Pacific. I had an outage of about 4.5 hours on the evening of March 26. Power came back around 00:41 on the 27th. These are the most recent entries, nothing afterwards.Mar 27 00:41:15 dpinger 88489 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:41:17 dpinger 88489 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:44:31 dpinger 88489 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:44:32 dpinger 88489 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:44:35 dpinger 88489 exiting on signal 15
Mar 27 00:44:47 dpinger 51525 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:44:49 dpinger 51525 exiting on signal 15
Mar 27 00:44:49 dpinger 93959 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:44:49 dpinger 94765 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:44:49 dpinger 94765 exiting on signal 15
Mar 27 00:44:49 dpinger 93959 exiting on signal 15
Mar 27 00:44:49 dpinger 1126 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:44:49 dpinger 2065 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:44:51 dpinger 2065 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:44:51 dpinger 1126 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:44:57 dpinger 2065 exiting on signal 15
Mar 27 00:44:57 dpinger 1126 exiting on signal 15
Mar 27 00:44:57 dpinger 66493 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:44:57 dpinger 66831 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:44:59 dpinger 66493 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:45:00 dpinger 66831 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:53:31 dpinger 26142 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:53:32 dpinger 26142 exiting on signal 15
Mar 27 00:53:32 dpinger 49400 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:53:34 dpinger 49400 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:53:35 dpinger 49400 exiting on signal 15
Mar 27 00:53:35 dpinger 15506 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:53:35 dpinger 14559 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:53:35 dpinger 15506 exiting on signal 15
Mar 27 00:53:35 dpinger 14559 exiting on signal 15
Mar 27 00:53:35 dpinger 24480 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:53:37 dpinger 51260 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:53:38 dpinger 24480 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:53:39 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:55:53 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:54 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 00:55:54 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:54 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 00:55:54 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:55 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 00:55:55 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:55 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 00:55:56 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:56 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 00:55:56 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:56 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 00:55:57 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:57 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 00:55:57 dpinger 51260 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 00:55:57 dpinger 24480 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 00:55:57 dpinger 51260 exiting on signal 15
Mar 27 00:55:57 dpinger 24480 exiting on signal 15
Mar 27 00:56:03 dpinger 23612 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:56:03 dpinger 23612 exiting on signal 15
Mar 27 00:56:03 dpinger 29238 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:56:05 dpinger 29238 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:56:05 dpinger 29238 exiting on signal 15
Mar 27 00:56:05 dpinger 3033 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:56:05 dpinger 5183 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:56:07 dpinger 3033 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:56:07 dpinger 5183 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:56:10 dpinger 5183 exiting on signal 15
Mar 27 00:56:10 dpinger 3033 exiting on signal 15
Mar 27 00:56:10 dpinger 94668 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:56:10 dpinger 95170 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 00:56:12 dpinger 94668 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:56:12 dpinger 95170 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 00:59:58 dpinger 49488 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 00:59:59 dpinger 49488 exiting on signal 15
Mar 27 00:59:59 dpinger 62928 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:00:01 dpinger 62928 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:00:02 dpinger 62928 exiting on signal 15
Mar 27 01:00:02 dpinger 49893 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:00:02 dpinger 50351 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:00:02 dpinger 50351 exiting on signal 15
Mar 27 01:00:02 dpinger 49893 exiting on signal 15
Mar 27 01:00:02 dpinger 69666 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:00:03 dpinger 69940 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:00:04 dpinger 69666 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:00:05 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:01:42 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:42 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 01:01:43 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:43 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 01:01:43 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:43 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 01:01:44 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:44 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 50
Mar 27 01:01:44 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:45 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:01:45 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:45 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:01:46 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:46 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:01:46 dpinger 69940 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: sendto error: 50
Mar 27 01:01:46 dpinger 69666 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:01:46 dpinger 69940 exiting on signal 15
Mar 27 01:01:46 dpinger 69666 exiting on signal 15
Mar 27 01:04:02 dpinger 51182 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:03 dpinger 51182 WAN_DHCP 76.132.78.1: sendto error: 49
Mar 27 01:04:03 dpinger 51182 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:04 dpinger 51182 exiting on signal 15
Mar 27 01:04:04 dpinger 92194 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:04:04 dpinger 92194 exiting on signal 15
Mar 27 01:04:04 dpinger 9667 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:04:06 dpinger 9667 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:04:07 dpinger 9667 exiting on signal 15
Mar 27 01:04:08 dpinger 1489 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:10 dpinger 1489 exiting on signal 15
Mar 27 01:04:10 dpinger 85044 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:10 dpinger 86926 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:04:10 dpinger 86926 exiting on signal 15
Mar 27 01:04:10 dpinger 85044 exiting on signal 15
Mar 27 01:04:10 dpinger 4258 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:10 dpinger 6130 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:04:12 dpinger 4258 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:12 dpinger 6130 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:04:12 dpinger 4258 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:04:12 dpinger 4258 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:13 dpinger 4258 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:13 dpinger 4258 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:14 dpinger 4258 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:15 dpinger 4258 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:15 dpinger 4258 WAN_DHCP 76.132.78.1: sendto error: 65
Mar 27 01:04:15 dpinger 6130 exiting on signal 15
Mar 27 01:04:15 dpinger 4258 exiting on signal 15
Mar 27 01:04:18 dpinger 25670 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:20 dpinger 25670 exiting on signal 15
Mar 27 01:04:20 dpinger 93336 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:20 dpinger 94341 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:04:20 dpinger 93336 exiting on signal 15
Mar 27 01:04:20 dpinger 96594 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:20 dpinger 94341 exiting on signal 15
Mar 27 01:04:20 dpinger 340 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:04:22 dpinger 96594 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:04:22 dpinger 340 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:04:25 dpinger 340 exiting on signal 15
Mar 27 01:04:25 dpinger 96594 exiting on signal 15
Mar 27 01:04:25 dpinger 16429 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:04:25 dpinger 16861 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:04:27 dpinger 16429 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:04:27 dpinger 16861 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:08:16 dpinger 32273 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:08:17 dpinger 32273 exiting on signal 15
Mar 27 01:08:17 dpinger 53452 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:08:19 dpinger 53452 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:08:20 dpinger 53452 exiting on signal 15
Mar 27 01:08:20 dpinger 75680 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:08:20 dpinger 74712 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:08:20 dpinger 75680 exiting on signal 15
Mar 27 01:08:20 dpinger 74712 exiting on signal 15
Mar 27 01:08:20 dpinger 93045 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr 76.132.78.1 bind_addr 76.132.78.66 identifier "WAN_DHCP "
Mar 27 01:08:22 dpinger 11859 send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% alarm_hold 10000ms dest_addr fe80::21c:73ff:fe00:99%ix0 bind_addr fe80::a236:9fff:fefa:8a30%ix0 identifier "WAN_DHCP6 "
Mar 27 01:08:22 dpinger 93045 WAN_DHCP 76.132.78.1: Alarm latency 0us stddev 0us loss 100%
Mar 27 01:08:24 dpinger 11859 WAN_DHCP6 fe80::21c:73ff:fe00:99%ix0: Alarm latency 0us stddev 0us loss 100% -
@madbrain Instead of looking for ways to restart everything, try to figure out the least destructive way to restart the connection. That is what I did. The problem was fixed without a reboot, I believe I just went to the Interfaces/(the wan that was down), not change anything, "save" and apply changes. That forced a DHCREQUEST to go out... Again, I don't remember but surely not a system restart.
If this problem happens enough for you to think about ways to circumvent it, you may want to be more elegant, and once you know how to get it going again with simple commands, and no major system restarts, you should be able to create bash script that can be activated from cron, that monitors the connection and fixes it.
In pfSense, everything you can do via GUI, you can do via CLI. And if you can do via CLI, you can automate it.
PS: AMD 5700g? How big is your network? Do you really need so much power? Anyway, only a curiosity. I am very happy with Intel Celeron J4125 ;-)
-
@fbrunken Here are the "routing" entries from the same outage.
Mar 27 00:42:20 miniupnpd 43831 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 00:42:20 miniupnpd 43831 Cannot get IP address for ext interface ix0. Network is down
Mar 27 00:42:20 miniupnpd 43831 HTTP listening on port 2189
Mar 27 00:42:20 miniupnpd 43831 no HTTP IPv6 address, disabling IPv6
Mar 27 00:53:52 miniupnpd 69728 HTTP listening on port 2189
Mar 27 00:53:52 miniupnpd 69728 HTTP IPv6 address given to control points : [2601:646:9d80:fdb:a236:9fff:fefa:8a31]
Mar 27 00:53:52 miniupnpd 69728 setsockopt(udp, IPV6_RECVPKTINFO): Invalid argument
Mar 27 00:55:55 miniupnpd 69728 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 00:55:55 miniupnpd 69728 Cannot get IP address for ext interface ix0. Network is down
Mar 27 00:55:55 miniupnpd 69728 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 00:55:55 miniupnpd 69728 Cannot get IP address for ext interface ix0. Network is down
Mar 27 01:00:18 miniupnpd 12514 HTTP listening on port 2189
Mar 27 01:00:18 miniupnpd 12514 HTTP IPv6 address given to control points : [2601:646:9d80:fdb:a236:9fff:fefa:8a31]
Mar 27 01:00:18 miniupnpd 12514 setsockopt(udp, IPV6_RECVPKTINFO): Invalid argument
Mar 27 01:01:44 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:01:44 miniupnpd 12514 Cannot get IP address for ext interface ix0. Network is down
Mar 27 01:01:44 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:01:44 miniupnpd 12514 Cannot get IP address for ext interface ix0. Network is down
Mar 27 01:02:29 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:02:29 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:04:03 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:04:03 miniupnpd 12514 Cannot get IP address for ext interface ix0. Network is down
Mar 27 01:04:06 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:04:06 miniupnpd 12514 Cannot get IP address for ext interface ix0. Network is down
Mar 27 01:04:11 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:04:11 miniupnpd 12514 Cannot get IP address for ext interface ix0. Network is down
Mar 27 01:04:12 miniupnpd 12514 ioctl(s, SIOCGIFADDR, ...): Can't assign requested address
Mar 27 01:04:12 miniupnpd 12514 Cannot get IP address for ext interface ix0. Network is down
Mar 27 01:08:36 miniupnpd 4019 HTTP listening on port 2189
Mar 27 01:08:36 miniupnpd 4019 HTTP IPv6 address given to control points : [2601:646:9d80:fdb:a236:9fff:fefa:8a31]
Mar 27 01:08:36 miniupnpd 4019 setsockopt(udp, IPV6_RECVPKTINFO): Invalid argument
Mar 28 15:35:16 miniupnpd 4019 upnp_event_recv: recv(): Connection reset by peer
Mar 28 15:35:16 miniupnpd 4019 upnpevents_processfds: 0x3606dfa38080, remove subscriber uuid:72ea0112-ed53-11ee-b5e0-a0369ffa8a30 after an ERROR cb: http://192.168.100.3:2869/upnp/eventing/elxxsetsth -
@fbrunken I have 170 static DHCP reservations. Big house, with lots of IoT devices. And that's not counting the 43 Z-Wave devices. And about 15 Yolink devices. Those don't get IPs.
-
@fbrunken I will try to reproduce the problem first, then see if I can force fix it without reboot/power cycle. But in the past, I did not succeed. I will see if bringing WAN interface down/up works.
I hope this works. Even if it does, I'm not sure if it is entirely satisfactory, as I guess the script will not be saved as part of pfSense backups, right ? -
@madbrain the script would be yours. you can keep it in your file server somewhere. in pfsense, it can run from the root home directory. keep it simple...
-
@fbrunken Simple for me would be to have a single-file backup that I can restore as needed, without manual config change.
Anyway, I just turned off power to my two UPSes. Waited about a minute for all equipment to be cold. Then powered them back on. pfSense behaved as expected. Internet became available as soon as the cable modem synced.
I'm not sure what's different about the other power outages. Perhaps the local cable company equipment also ran out of power, and needs some time to restart, too, which could change the timing. I'm just guessing at this point.