• Hi

    I use pfSense to create the PPPoE connection to my ISP.
    I had an issue with my internet today where pfSense showed my WAN as down, yet my ISP could see that I had authenticated.

    The Gateway log just showed: (I've masked part of the IP Address)

    Jan 4 14:40:43 dpinger WAN_PPPOE 212.x.x.x: sendto error: 65
    Jan 4 14:40:43 dpinger WAN_PPPOE 212.x.x.x: sendto error: 65
    Jan 4 14:40:42 dpinger WAN_PPPOE 212.x.x.x: sendto error: 65
    Jan 4 14:40:42 dpinger WAN_PPPOE 212.x.x.x: sendto error: 65
    Jan 4 14:40:41 dpinger WAN_PPPOE 212.x.x.x: sendto error: 65
    Jan 4 14:40:41 dpinger WAN_PPPOE 212.x.x.x: sendto error: 65
    Jan 4 14:40:40 dpinger WAN_PPPOE 212.x.x.x: sendto error: 65

    When I clicked 'connect' on the WAN Interface I got the status and PPPoE as UP, but I only got an IPv6 Link Local Address and DNS Address as 127.0.0.1, nothing for IPv4, Subnet or Gateway.

    Is there anyway I can find out why this failed to work ? Why did the ISP see my connection as authenticated when pfSense didn't show it connected correctly ?

    Thanks

  • Netgate Administrator

    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

  • Netgate Administrator

    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

  • Netgate Administrator

    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

  • Netgate Administrator

    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.html

    Steve


  • 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

  • Netgate Administrator

    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/Jutdw1cr

    91 address is my static
    212 address is the ISP

    Thanks for taking a look at this.

    Regards

  • LAYER 8 Global Moderator

    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

  • Netgate Administrator

    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

  • Netgate Administrator

    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/20

    When 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

  • Netgate Administrator

    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