WAN Down - Unable to connect.
-
Check the PPP log. It will usually show the IP address and gateway you're given there.
That gateway log would be expected if there's no default IPv4 route.
Steve
-
Hi
This happened again. Last night the internet seemed to be playing up so I rebooted pfSense and all was well.This morning at around 06:23 the Internet was down. I had to reboot the BT Modem and pfSense to get this running.
The gateways.log showed:
Where 212.Y.Y.Y is the ISP
91.X.X.X is my Static IP
10.Z.Z.Z openVPN Link to PIA.Jan 23 06:22:30 pfSense dpinger: WAN_PPPOE 212.Y.Y.Y: Alarm latency 13941us stddev 877us loss 21% Jan 23 08:06:20 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 212.Y.Y.Y bind_addr 91.X.X.X identifier "WAN_PPPOE " Jan 23 08:06:22 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 212.Y.Y.Y bind_addr 91.X.X.X identifier "WAN_PPPOE " Jan 23 08:06:29 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 212.Y.Y.Y bind_addr 91.X.X.X identifier "WAN_PPPOE " Jan 23 08:06:29 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 8.8.8.8 bind_addr 10.Z.Z.Z identifier "PIA_VPNV4 "
The ppp.log shows the following:
Jan 23 06:23:29 pfSense ppp: [wan_link0] LCP: no reply to 1 echo request(s) Jan 23 06:23:39 pfSense ppp: [wan_link0] LCP: no reply to 2 echo request(s) Jan 23 06:23:49 pfSense ppp: [wan_link0] LCP: no reply to 3 echo request(s) Jan 23 06:23:59 pfSense ppp: [wan_link0] LCP: no reply to 4 echo request(s) Jan 23 06:24:09 pfSense ppp: [wan_link0] LCP: no reply to 5 echo request(s) Jan 23 06:24:09 pfSense ppp: [wan_link0] LCP: peer not responding to echo requests Jan 23 06:24:09 pfSense ppp: [wan_link0] LCP: state change Opened --> Stopping Jan 23 06:24:09 pfSense ppp: [wan_link0] Link: Leave bundle "wan" Jan 23 06:24:09 pfSense ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps Jan 23 06:24:09 pfSense ppp: [wan] IPCP: Close event Jan 23 06:24:09 pfSense ppp: [wan] IPCP: state change Opened --> Closing Jan 23 06:24:09 pfSense ppp: [wan] IPCP: SendTerminateReq #4 Jan 23 06:24:09 pfSense ppp: [wan] IPCP: LayerDown Jan 23 06:24:09 pfSense ppp: [wan] IPV6CP: Close event Jan 23 06:24:09 pfSense ppp: [wan] IPV6CP: state change Opened --> Closing Jan 23 06:24:09 pfSense ppp: [wan] IPV6CP: SendTerminateReq #2 Jan 23 06:24:09 pfSense ppp: [wan] IPV6CP: LayerDown Jan 23 06:24:10 pfSense ppp: [wan] IFACE: Down event Jan 23 06:24:10 pfSense ppp: [wan] IFACE: Rename interface pppoe1 to pppoe1 Jan 23 06:24:10 pfSense ppp: [wan] IPCP: Down event Jan 23 06:24:10 pfSense ppp: [wan] IPCP: LayerFinish Jan 23 06:24:10 pfSense ppp: [wan] IPCP: state change Closing --> Initial Jan 23 06:24:10 pfSense ppp: [wan] IPV6CP: Down event Jan 23 06:24:10 pfSense ppp: [wan] IPV6CP: LayerFinish Jan 23 06:24:10 pfSense ppp: [wan] Bundle: No NCPs left. Closing links... Jan 23 06:24:10 pfSense ppp: [wan] IPV6CP: state change Closing --> Initial Jan 23 06:24:10 pfSense ppp: [wan_link0] LCP: SendTerminateReq #11 Jan 23 06:24:10 pfSense ppp: [wan_link0] LCP: LayerDown Jan 23 06:24:12 pfSense ppp: [wan_link0] LCP: SendTerminateReq #12 Jan 23 06:24:15 pfSense ppp: [wan_link0] LCP: state change Stopping --> Stopped Jan 23 06:24:15 pfSense ppp: [wan_link0] LCP: LayerFinish Jan 23 06:24:15 pfSense ppp: [wan_link0] PPPoE: connection closed Jan 23 06:24:15 pfSense ppp: [wan_link0] Link: DOWN event Jan 23 06:24:15 pfSense ppp: [wan_link0] LCP: Down event Jan 23 06:24:15 pfSense ppp: [wan_link0] LCP: state change Stopped --> Starting Jan 23 06:24:15 pfSense ppp: [wan_link0] LCP: LayerStart Jan 23 06:24:15 pfSense ppp: [wan_link0] Link: reconnection attempt 1 in 4 seconds Jan 23 06:24:19 pfSense ppp: [wan_link0] Link: reconnection attempt 1 Jan 23 06:24:19 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jan 23 06:24:28 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jan 23 06:24:28 pfSense ppp: [wan_link0] Link: DOWN event Jan 23 06:24:28 pfSense ppp: [wan_link0] LCP: Down event Jan 23 06:24:28 pfSense ppp: [wan_link0] Link: reconnection attempt 2 in 1 seconds Jan 23 06:24:29 pfSense ppp: [wan_link0] Link: reconnection attempt 2 Jan 23 06:24:29 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jan 23 06:24:38 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jan 23 06:24:38 pfSense ppp: [wan_link0] Link: DOWN event Jan 23 06:24:38 pfSense ppp: [wan_link0] LCP: Down event Jan 23 06:24:38 pfSense ppp: [wan_link0] Link: reconnection attempt 3 in 2 seconds Jan 23 06:24:40 pfSense ppp: [wan_link0] Link: reconnection attempt 3 Jan 23 06:24:40 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jan 23 06:24:49 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jan 23 06:24:49 pfSense ppp: [wan_link0] Link: DOWN event Jan 23 06:24:49 pfSense ppp: [wan_link0] LCP: Down event
This counts down and repeats until I manually tried to connect at 07:25
Jan 23 07:25:46 pfSense ppp: Multi-link PPP daemon for FreeBSD Jan 23 07:25:46 pfSense ppp: Jan 23 07:25:46 pfSense ppp: process 6065 started, version 5.8 (nobody@pfSense_v2_4_4_amd64-pfSense_v2_4_4-job-01 11:43 4-Oct-2018) Jan 23 07:25:46 pfSense ppp: caught fatal signal TERM Jan 23 07:25:46 pfSense ppp: [wan] IFACE: Close event Jan 23 07:25:46 pfSense ppp: [wan] IPCP: Close event Jan 23 07:25:46 pfSense ppp: [wan] IPV6CP: Close event Jan 23 07:25:46 pfSense ppp: waiting for process 7885 to die... Jan 23 07:25:47 pfSense ppp: waiting for process 7885 to die... Jan 23 07:25:48 pfSense ppp: waiting for process 7885 to die... Jan 23 07:25:48 pfSense ppp: [wan] Bundle: Shutdown Jan 23 07:25:48 pfSense ppp: [wan_link0] Link: Shutdown Jan 23 07:25:48 pfSense ppp: process 7885 terminated Jan 23 07:25:49 pfSense ppp: web: web is not running Jan 23 07:25:49 pfSense ppp: [wan] Bundle: Interface ng0 created Jan 23 07:25:49 pfSense ppp: [wan_link0] Link: OPEN event Jan 23 07:25:49 pfSense ppp: [wan_link0] LCP: Open event Jan 23 07:25:49 pfSense ppp: [wan_link0] LCP: state change Initial --> Starting Jan 23 07:25:49 pfSense ppp: [wan_link0] LCP: LayerStart Jan 23 07:25:49 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jan 23 07:25:57 pfSense ppp: Multi-link PPP daemon for FreeBSD Jan 23 07:25:57 pfSense ppp: Jan 23 07:25:57 pfSense ppp: process 55163 started, version 5.8 (nobody@pfSense_v2_4_4_amd64-pfSense_v2_4_4-job-01 11:43 4-Oct-2018) Jan 23 07:25:57 pfSense ppp: waiting for process 6065 to die... Jan 23 07:25:57 pfSense ppp: caught fatal signal TERM Jan 23 07:25:57 pfSense ppp: [wan] IFACE: Close event Jan 23 07:25:57 pfSense ppp: [wan] IPCP: Close event Jan 23 07:25:57 pfSense ppp: [wan] IPV6CP: Close event Jan 23 07:25:58 pfSense ppp: waiting for process 6065 to die... Jan 23 07:25:58 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jan 23 07:25:58 pfSense ppp: [wan_link0] Link: DOWN event Jan 23 07:25:58 pfSense ppp: [wan_link0] Link: giving up after 0 reconnection attempts Jan 23 07:25:58 pfSense ppp: [wan_link0] LCP: Close event Jan 23 07:25:58 pfSense ppp: [wan_link0] LCP: state change Starting --> Initial Jan 23 07:25:58 pfSense ppp: [wan_link0] LCP: LayerFinish Jan 23 07:25:58 pfSense ppp: [wan_link0] LCP: Down event Jan 23 07:25:59 pfSense ppp: [wan] Bundle: Shutdown Jan 23 07:25:59 pfSense ppp: [wan_link0] Link: Shutdown Jan 23 07:25:59 pfSense ppp: process 6065 terminated Jan 23 07:25:59 pfSense ppp: web: web is not running Jan 23 07:25:59 pfSense ppp: [wan] Bundle: Interface ng0 created Jan 23 07:25:59 pfSense ppp: [wan_link0] Link: OPEN event Jan 23 07:25:59 pfSense ppp: [wan_link0] LCP: Open event Jan 23 07:25:59 pfSense ppp: [wan_link0] LCP: state change Initial --> Starting Jan 23 07:25:59 pfSense ppp: [wan_link0] LCP: LayerStart Jan 23 07:25:59 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jan 23 07:26:08 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jan 23 07:26:08 pfSense ppp: [wan_link0] Link: DOWN event Jan 23 07:26:08 pfSense ppp: [wan_link0] LCP: Down event Jan 23 07:26:08 pfSense ppp: [wan_link0] Link: reconnection attempt 1 in 3 seconds Jan 23 07:26:11 pfSense ppp: [wan_link0] Link: reconnection attempt 1 Jan 23 07:26:11 pfSense ppp: [wan_link0] PPPoE: Connecting to '' Jan 23 07:26:20 pfSense ppp: [wan_link0] PPPoE connection timeout after 9 seconds Jan 23 07:26:20 pfSense ppp: [wan_link0] Link: DOWN event Jan 23 07:26:20 pfSense ppp: [wan_link0] LCP: Down event
Again this counts down and repeats until the reboots.
Any ideas what is going on ? I have raised this with my ISP as well.
Thanks
-
Not really. It looks like the other end is just not responding.
Are you running 2.4.4p2? If not upgrade to that.
Steve
-
Thanks
I'm currently running 2.4.4, its just happened again so will upgrade later this evening to 2.4.4p2
-
Ah, OK. There were issues in 2.4.4 most of which were corrected in p1 but, yeah, upgrade before digging further this might well be fixed already.
Steve
-
@stephenw10 thanks for the reply.
I've updated to 2.4.4p2 and will see how things go.
-
Hi.
This has happened again. When it did I meant to check the phone line to ensure I'd got dial tone, but I forgot.
The only way to get this working again was to reboot my pfSense box.I'm running 2.4.4p2.
Gateway.log showed:
Feb 5 22:15:14 pfSense dpinger: OPT3PIA_VPNV4 8.8.8.8: Alarm latency 16145us stddev 2343us loss 22% Feb 5 22:15:17 pfSense dpinger: WAN_PPPOE 212.Y.Y.Y: Alarm latency 13419us stddev 893us loss 21% Feb 5 22:17:11 pfSense dpinger: OPT3PIA_VPNV4 8.8.8.8: Clear latency 16182us stddev 2241us loss 10% Feb 5 22:17:11 pfSense dpinger: WAN_PPPOE 212.Y.Y.Y: Clear latency 13463us stddev 873us loss 7% Feb 5 22:17:46 pfSense dpinger: OPT3PIA_VPNV4 8.8.8.8: Alarm latency 16336us stddev 4056us loss 21% Feb 5 22:17:58 pfSense dpinger: WAN_PPPOE 212.Y.Y.Y: Alarm latency 14359us stddev 5503us loss 21% Feb 5 22:19:36 pfSense dpinger: WAN_PPPOE 212.Y.Y.Y: Clear latency 15778us stddev 9835us loss 10% Feb 5 22:19:38 pfSense dpinger: OPT3PIA_VPNV4 8.8.8.8: Clear latency 18087us stddev 8345us loss 10% Feb 5 22:21:00 pfSense dpinger: OPT3PIA_VPNV4 8.8.8.8: Alarm latency 21399us stddev 15991us loss 21% Feb 5 22:21:01 pfSense dpinger: WAN_PPPOE 212.Y.Y.Y: Alarm latency 17491us stddev 14501us loss 21% Feb 5 22:33:02 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 212.Y.Y.Y bind_addr 91.X.X.X identifier "WAN_PPPOE " Feb 5 22:33:04 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 212.Y.Y.Y bind_addr 91.X.X.X identifier "WAN_PPPOE " Feb 5 22:33:11 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 212.Y.Y.Y bind_addr 91.X.X.X identifier "WAN_PPPOE " Feb 5 22:33:11 pfSense dpinger: send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 8.8.8.8 bind_addr 10.Z.Z.Z identifier "PIA_VPNV4 "
The ppp.log has the correct timestamp on the file, but is only shows the following:
Feb 2 15:51:40 pfSense ppp: [wan_link0] LCP: LayerDown Feb 2 15:51:40 pfSense ppp: [wan_link0] LCP: SendConfigReq #6 Feb 2 15:51:40 pfSense ppp: [wan_link0] MRU 1492 Feb 2 15:51:40 pfSense ppp: [wan_link0] MAGICNUM 0x60ac7bda Feb 2 15:51:40 pfSense ppp: [wan_link0] LCP: SendConfigAck #113 Feb 2 15:51:40 pfSense ppp: [wan_link0] MRU 1492 Feb 2 15:51:40 pfSense ppp: [wan_link0] AUTHPROTO CHAP MD5 Feb 2 15:51:40 pfSense ppp: [wan_link0] MAGICNUM 0x3f0936dc Feb 2 15:51:40 pfSense ppp: [wan_link0] LCP: state change Opened --> Ack-Sent Feb 2 15:51:40 pfSenseCLOG<▒▒▒^C 544 -rw------- 1 root wheel 500K Feb 5 22:33 ppp.log stat ppp.log 116 160561 -rw------- 1 root wheel 333272 511488 "Feb 5 22:39:36 2019" "Feb 5 22:33:09 2019" "Feb 5 22:33:09 2019" "Jun 22 18:23:22 2018" 32768 1088 0 ppp.log
Which I think is around the last time it happened.
How do I resolve this and how do I get a working ppp.log ?Thanks
-
Looks like you are trying to view the the circular log files (clog) as plain text.
https://docs.netgate.com/pfsense/en/latest/monitoring/working-with-binary-circular-logs-clog.htmlSteve
-
Thanks
I've now got the log, but each time I try to post it the message is being flagged as spam.Any way I can get this to you ?
Thanks
-
Try posting it in
</>
code brackets or as an attachment. Or link to pastebin etc maybe.Steve
-
Hi stephenw10
This is the pastebin to the log.
https://pastebin.com/Jutdw1cr91 address is my static
212 address is the ISPThanks for taking a look at this.
Regards
-
Lets see if marks me as spam... Here is post from your pastebin
I don't get spam, I get
Please enter a shorter post. Posts can't be longer than 32767 character(s). -
My initial reply did get the message about the number of characters. I shortened it and then got the spam message.
I've attached the link to the output, hopefully it will show what's going on!
Thanks
-
It looks like it fails to authorise until this:
Feb 6 00:01:35 pfSense ppp: [wan_link0] LCP: LayerUp Feb 6 00:01:35 pfSense ppp: [wan_link0] CHAP: rec'd CHALLENGE #2 len: 29 Feb 6 00:01:35 pfSense ppp: [wan_link0] Name: "IDNetLNS" Feb 6 00:01:35 pfSense ppp: [wan_link0] CHAP: Using authname "000000@ISP.COM" Feb 6 00:01:35 pfSense ppp: [wan_link0] CHAP: sending RESPONSE #2 len: 38 Feb 6 00:01:35 pfSense ppp: [wan_link0] CHAP: rec'd SUCCESS #2 len: 4 Feb 6 00:01:35 pfSense ppp: [wan_link0] LCP: authorization successful
It tries other against other 'Names' and fails.
It also looks like the other end is closing the link:
Feb 5 22:33:01 pfSense ppp: [wan] IPCP: state change Ack-Sent --> Opened Feb 5 22:33:01 pfSense ppp: [wan] IPCP: LayerUp Feb 5 22:33:01 pfSense ppp: [wan] 91.X.X.X -> 212.Y.Y.Y Feb 6 00:01:04 pfSense ppp: [wan_link0] LCP: rec'd Terminate Request #3 (Opened) Feb 6 00:01:04 pfSense ppp: [wan_link0] LCP: state change Opened --> Stopping
I assume you did nothing at that point?
Steve
-
The issue originally happened around 10:25 and I restarted my box at about 10:30/10:35
While this was happening I checked the phone, I had dial tone and a quiet line test sounded fine.
After the reboot the connection was up, I wasn't aware it had gone down again at 00:01
When this happens a reboot normally resolves it.. is there anything I can apart from reboot ?
My ISP can't see anything wrong and have suggested I try a different router.
My setup is:
BT OpenReach connected directly to BT master socket.
CAT5e connection to my pfSense box. This cable runs through a roof space to the other side of the house where my pfSense box is. I have a couple of other cables running this way for wireless access points and I've not had any drop outs from them so I don't think it's a cabling issue..Any ideas, it happening quiet often.
Thanks
-
Ah well that's interesting, so you didn't notice the drop at 'Feb 6 00:01:04'?
Is that ADSL or VDSL/FTTC? I have used both and they worked fine. I am close to an exchange which helps.
If you're using FTTC with the Openreach modem is it the Huawei or ECI model? I had to swap out the Huawei modem I had as it seems very susceptible to overheating. The ECI has been rock solid.
Steve
-
Hi
I didn't notice the drop at 00:01:04 as I was in bed !
This is UK FTTC, the exchange is quite a distance a way, but I'm less than 100 mtrs from the cabinet.
Connection on the Huawei HG612 is showing solid at the max of 80/20When this happens a restart of the HG612 doesn't help. I do have a ECI I could try if you think that will help.
Thanks
-
Well I can tell you struggled for a while with the HG612 and eventually swapped it out for an ECI and never looked back.
When it failed it usually stopped passing traffic completely so the PPPoE would go down. All the LEDs just remained solid on
it.I had thought you might be hitting this: https://redmine.pfsense.org/issues/9148
I saw that a few times in 2.4.4 but have not seen that since that patch was included in 2.4.4p1. I don't see that in your logs specifically either.
Unfortunately we can't see what happened that started the failure at 10.25. The first log entry shows the PPP session closing already:
Feb 5 22:27:14 pfSense ppp: [wan_link0] PPPoE: connection closed
However the failure at 00.01 was initiated from the remote side. It came back up by itself though.
If we can get the log showing the connection fail that might help. Not guarantied though.
I have nothing special set here and it "just works".
Steve