pfSense unable to recover Internet access after power outage
-
@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. -
@madbrain Hi and sorry for the delay. I made this very quick image here... Sorry, didn't take too long preparing it.
Important is:
- pfSense is your router/firewall into the internet, correct? In your case you have Comcast as ISP.
- The IP of your router is dynamic, as of this log, 76.x.x.66, correct? (I would not leave public IPs here...)
- I didn't take the time, but important is that you have a lot of HAOS and I suppose other devices in your network. Wired or wireless. Doesn't matter. Also, it doesn't matter if docker, VM instances, or physical devices, as long as they all need to go through pfSense to get to the internet.
So, I am not sure what the logs tell me. My problem was related to recovering from the outage without receiving a correct public IP. The CPE from my ISP, which I use in bridge mode, provided me with an IP that did not work... By forcing a DHCPREQUEST, I fixed the problem.
The log in my case that could clearly show that it wasn't getting fixed was the DHCP one. Yes, the DHCP log provides a log for when pfSense is the server as well as the client.
It is not clear to me, when did the problem finish or why. It started around 00:41, when were you able to get it going again? Do you have a monitor IP or it just uses the GW that comcast gives you, I suppose 76.x.x.1? Also, during the time that the problem was going on, did you check the status of your Gateway? In my dashboard I have Interfaces and Gateways always being shown. This way I can tell what IP address I have on my interface and if pfSense considers the Gateway online or offline.
-
@fbrunken Thanks for your response.
- yes, pfSense is my router firewall, and the ISP is Comcast
- yes, it's a dynamic IP
- yes, all my devices, wired or wireless, need to go through pfSense to reach the Internet
I don't believe I tried forcing a DHCPREQUEST to solve the issue.
I don't have a monitor IP. My WAN interface is just set to DHCP /DHCP6 to use whatever Comcast gives.
I don't recall the interfaces / gateways status at the time, unfortunately. Pretty sure I had to reboot at least the modem twice. Possibly pfSense too, but not certain.I wish I could recreate the problem, but I couldn't. on tuesday.
However, as of yesterday, I have a second ISP, Sail internet, with a rooftop fixed wireless antenna. Maybe I can reproduce it with their modem.I'm setting up dual WAN also. A bit complex with dynamic DNS and VPN in the picture. Sail internet only supports IPv4 also, not IPv6. Comcast does both. Hard to failover in that case. Anyway, I'm hoping to get rid of Comcast altogether as I hate their contract shenanigans.