Troubleshooting CenturyLink PPPoE Connection Drop
-
We get GB fiber from CenturyLink over PPPoE. We've recently had several occurrences of loss of Internet connectivity where the PPPoE connection goes down and pfSense tries over and over again to re-establish it. This goes on until the pfSense box is rebooted, at which point the connection comes back up immediately.
System pfSense Serial: GB712202819H0818 Netgate Device ID: b529d6c3f4d54cf5702d BIOS Vendor: American Megatrends Inc. Version: GB7 0.08 Release Date: Tue May 25 2021 Version 2.6.0-RELEASE (amd64) built on Mon Jan 31 19:57:53 UTC 2022 FreeBSD 12.3-STABLE The system is on the latest version. Version information updated at Thu Jun 8 15:42:01 PDT 2023 CPU Type Intel(R) Celeron(R) J4125 CPU @ 2.00GHz Current: 2000 MHz, Max: 2001 MHz 4 CPUs: 1 package(s) x 4 core(s) AES-NI CPU Crypto: Yes (inactive) QAT Crypto: No Hardware crypto Kernel PTI Disabled MDS Mitigation Inactive Uptime 05 Hours 40 Minutes 15 Seconds Current date/time Thu Jun 8 17:02:09 PDT 2023 DNS server(s) 127.0.0.1 205.171.3.65 205.171.2.65 Last config change Thu Jun 8 0:03:00 PDT 2023
What I want to determine is if this is a problem with CenturyLink, or pfSense is not doing the right thing to re-establish the connection.
One curiosity is the line in the Dashboard that says
Last config change Thu Jun 8 0:03:00 PDT 2023
There was nobody logged in at that time... what is this in reference to? Is it possible to determine what it thinks the config change was?
Here's a syslog extract from when the connection goes down at 03:37:58, and below from just after the reboot. Suggestions for further troubleshooting welcome.
Jun 8 01:01:00 fw php[93722]: rc.dyndns.update: phpDynDNS (janus.goow.org): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jun 8 01:01:01 fw php[93722]: rc.dyndns.update: phpDynDNS (wiki.goow.org): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jun 8 03:37:58 fw kernel: re0: watchdog timeout Jun 8 03:37:58 fw kernel: re0: link state changed to DOWN Jun 8 03:37:58 fw kernel: re0.201: link state changed to DOWN Jun 8 03:37:58 fw check_reload_status[408]: Linkup starting re0 Jun 8 03:37:58 fw check_reload_status[408]: Linkup starting re0.201 Jun 8 03:37:59 fw check_reload_status[408]: Reloading filter Jun 8 03:37:59 fw check_reload_status[408]: Reloading filter Jun 8 03:38:02 fw check_reload_status[408]: Linkup starting re0 Jun 8 03:38:02 fw kernel: re0: link state changed to UP Jun 8 03:38:02 fw kernel: re0.201: link state changed to UP Jun 8 03:38:02 fw check_reload_status[408]: Linkup starting re0.201 Jun 8 03:38:03 fw check_reload_status[408]: Reloading filter Jun 8 03:38:03 fw ppp[74083]: Multi-link PPP daemon for FreeBSD Jun 8 03:38:03 fw ppp[74083]: Jun 8 03:38:03 fw ppp[74083]: process 74083 started, version 5.9 Jun 8 03:38:03 fw ppp[74083]: waiting for process 10023 to die... Jun 8 03:38:03 fw ppp[10023]: caught fatal signal TERM Jun 8 03:38:03 fw ppp[10023]: [wan] IFACE: Close event Jun 8 03:38:03 fw ppp[10023]: [wan] IPCP: Close event Jun 8 03:38:03 fw ppp[10023]: [wan] IPCP: state change Opened --> Closing Jun 8 03:38:03 fw ppp[10023]: [wan] IPCP: SendTerminateReq #4 Jun 8 03:38:03 fw ppp[10023]: [wan] IPCP: LayerDown Jun 8 03:38:03 fw php-fpm[369]: /rc.linkup: Default gateway setting Interface WAN_PPPOE Gateway as default. Jun 8 03:38:03 fw php-fpm[369]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Jun 8 03:38:03 fw check_reload_status[408]: Restarting IPsec tunnels Jun 8 03:38:04 fw check_reload_status[408]: Rewriting resolv.conf Jun 8 03:38:04 fw ppp[10023]: [wan] IFACE: Removing IPv4 address from pppoe1 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address Jun 8 03:38:04 fw ppp[10023]: [wan] IFACE: Down event Jun 8 03:38:04 fw ppp[10023]: [wan] IFACE: Rename interface pppoe1 to pppoe1 Jun 8 03:38:04 fw ppp[10023]: [wan] IFACE: Set description "WAN" Jun 8 03:38:04 fw ppp[74083]: waiting for process 10023 to die... Jun 8 03:38:05 fw ppp[74083]: waiting for process 10023 to die... Jun 8 03:38:06 fw ppp[10023]: [wan] Bundle: Shutdown Jun 8 03:38:06 fw ppp[10023]: [wan_link0] Link: Shutdown Jun 8 03:38:06 fw ppp[10023]: process 10023 terminated Jun 8 03:38:06 fw ppp[74083]: web: web is not running Jun 8 03:38:06 fw ppp[74083]: [wan] Bundle: Interface ng0 created Jun 8 03:38:06 fw ppp[74083]: [wan_link0] Link: OPEN event Jun 8 03:38:06 fw kernel: ng0: changing name to 'pppoe1' Jun 8 03:38:06 fw ppp[74083]: [wan_link0] LCP: Open event Jun 8 03:38:06 fw ppp[74083]: [wan_link0] LCP: state change Initial --> Starting Jun 8 03:38:06 fw ppp[74083]: [wan_link0] LCP: LayerStart Jun 8 03:38:06 fw ppp[74083]: [wan_link0] PPPoE: Connecting to '' Jun 8 03:38:07 fw rc.gateway_alarm[21179]: >>> Gateway alarm: WAN_PPPOE (Addr:207.225.84.48 Alarm:1 RTT:3.553ms RTTsd:4.728ms Loss:21%) Jun 8 03:38:07 fw check_reload_status[408]: updating dyndns WAN_PPPOE Jun 8 03:38:07 fw check_reload_status[408]: Restarting IPsec tunnels Jun 8 03:38:07 fw check_reload_status[408]: Restarting OpenVPN tunnels/interfaces Jun 8 03:38:07 fw check_reload_status[408]: Reloading filter Jun 8 03:38:07 fw check_reload_status[408]: Linkup starting re0 Jun 8 03:38:07 fw kernel: re0: watchdog timeout Jun 8 03:38:07 fw kernel: re0: link state changed to DOWN Jun 8 03:38:07 fw kernel: re0.201: link state changed to DOWN Jun 8 03:38:07 fw check_reload_status[408]: Linkup starting re0.201 Jun 8 03:38:08 fw check_reload_status[408]: updating dyndns wan Jun 8 03:38:08 fw check_reload_status[408]: Reloading filter Jun 8 03:38:08 fw php-fpm[10114]: /rc.openvpn: Gateway, none 'available' for inet, use the first one configured. 'WAN_PPPOE' Jun 8 03:38:08 fw php-fpm[10114]: /rc.openvpn: Gateway, none 'available' for inet6, use the first one configured. '' Jun 8 03:38:08 fw php-fpm[370]: /rc.dyndns.update: Dynamic DNS noip (janus.goow.org): IP address could not be extracted from Check IP Service Jun 8 03:38:08 fw php-fpm[370]: /rc.dyndns.update: Dynamic DNS (janus.goow.org) There was an error trying to determine the public IP for interface - wan (pppoe1 ). Jun 8 03:38:09 fw php-fpm[369]: /rc.dyndns.update: Dynamic DNS noip (janus.goow.org): IP address could not be extracted from Check IP Service Jun 8 03:38:09 fw php-fpm[369]: /rc.dyndns.update: Dynamic DNS (janus.goow.org) There was an error trying to determine the public IP for interface - wan (pppoe1 ). Jun 8 03:38:09 fw php-fpm[370]: /rc.dyndns.update: Dynamic DNS noip (wiki.goow.org): IP address could not be extracted from Check IP Service Jun 8 03:38:09 fw php-fpm[370]: /rc.dyndns.update: Dynamic DNS (wiki.goow.org) There was an error trying to determine the public IP for interface - wan (pppoe1 ). Jun 8 03:38:10 fw php-fpm[369]: /rc.dyndns.update: Dynamic DNS noip (wiki.goow.org): IP address could not be extracted from Check IP Service Jun 8 03:38:10 fw php-fpm[369]: /rc.dyndns.update: Dynamic DNS (wiki.goow.org) There was an error trying to determine the public IP for interface - wan (pppoe1 ). Jun 8 03:38:12 fw check_reload_status[408]: Linkup starting re0 Jun 8 03:38:12 fw kernel: re0: link state changed to UP Jun 8 03:38:12 fw kernel: re0.201: link state changed to UP Jun 8 03:38:12 fw check_reload_status[408]: Linkup starting re0.201 Jun 8 03:38:13 fw check_reload_status[408]: Reloading filter Jun 8 03:38:13 fw ppp[98010]: Multi-link PPP daemon for FreeBSD Jun 8 03:38:13 fw ppp[98010]: Jun 8 03:38:13 fw ppp[98010]: process 98010 started, version 5.9 Jun 8 03:38:13 fw ppp[98010]: waiting for process 74083 to die... Jun 8 03:38:13 fw ppp[74083]: caught fatal signal TERM Jun 8 03:38:13 fw ppp[74083]: [wan] IFACE: Close event Jun 8 03:38:13 fw ppp[74083]: [wan] IPCP: Close event Jun 8 03:38:13 fw php-fpm[10114]: /rc.linkup: Gateway, none 'available' for inet, use the first one configured. 'WAN_PPPOE' Jun 8 03:38:13 fw php-fpm[10114]: /rc.linkup: Gateway, none 'available' for inet6, use the first one configured. '' Jun 8 03:38:13 fw check_reload_status[408]: Restarting IPsec tunnels Jun 8 03:38:14 fw ppp[98010]: waiting for process 74083 to die... Jun 8 03:38:15 fw ppp[74083]: [wan] Bundle: Shutdown Jun 8 03:38:15 fw ppp[98010]: waiting for process 74083 to die... Jun 8 03:38:15 fw ppp[74083]: [wan_link0] Link: Shutdown Jun 8 03:38:15 fw ppp[74083]: process 74083 terminated Jun 8 03:38:15 fw vnstatd[60253]: Interface "pppoe1" disabled.
This repeats continuously until the system is rebooted, at which point the connection is immediately re-established.
Jun 8 11:22:10 fw ppp[9666]: Multi-link PPP daemon for FreeBSD Jun 8 11:22:10 fw ppp[9666]: Jun 8 11:22:10 fw ppp[9666]: process 9666 started, version 5.9 Jun 8 11:22:10 fw ppp[9666]: web: web is not running Jun 8 11:22:10 fw ppp[9666]: [wan] Bundle: Interface ng0 created Jun 8 11:22:10 fw ppp[9666]: [wan_link0] Link: OPEN event Jun 8 11:22:10 fw kernel: ng0: changing name to 'pppoe1' Jun 8 11:22:10 fw ppp[9666]: [wan_link0] LCP: Open event Jun 8 11:22:10 fw ppp[9666]: [wan_link0] LCP: state change Initial --> Starting Jun 8 11:22:10 fw ppp[9666]: [wan_link0] LCP: LayerStart . . . Jun 8 11:22:10 fw kernel: lo0: link state changed to UP Jun 8 11:22:10 fw check_reload_status[408]: Linkup starting re0 Jun 8 11:22:10 fw kernel: re0: link state changed to DOWN Jun 8 11:22:10 fw kernel: vlan0: changing name to 're0.201' Jun 8 11:22:10 fw check_reload_status[408]: Linkup starting re1 Jun 8 11:22:10 fw kernel: re1: link state changed to DOWN Jun 8 11:22:10 fw ppp[9666]: Multi-link PPP daemon for FreeBSD Jun 8 11:22:10 fw ppp[9666]: Jun 8 11:22:10 fw ppp[9666]: process 9666 started, version 5.9 Jun 8 11:22:10 fw ppp[9666]: web: web is not running Jun 8 11:22:10 fw ppp[9666]: [wan] Bundle: Interface ng0 created Jun 8 11:22:10 fw ppp[9666]: [wan_link0] Link: OPEN event Jun 8 11:22:10 fw kernel: ng0: changing name to 'pppoe1' Jun 8 11:22:10 fw ppp[9666]: [wan_link0] LCP: Open event Jun 8 11:22:10 fw ppp[9666]: [wan_link0] LCP: state change Initial --> Starting Jun 8 11:22:10 fw ppp[9666]: [wan_link0] LCP: LayerStart Jun 8 11:22:10 fw ppp[9666]: [wan_link0] PPPoE: Connecting to '' Jun 8 11:22:11 fw sshd[10723]: Server listening on :: port 22. Jun 8 11:22:11 fw sshd[10723]: Server listening on 0.0.0.0 port 22. Jun 8 11:22:11 fw sshguard[11382]: Now monitoring attacks. Jun 8 11:22:13 fw php[430]: rc.bootup: Resyncing OpenVPN instances. Jun 8 11:22:13 fw kernel: pflog0: promiscuous mode enabled Jun 8 11:22:14 fw php[430]: rc.bootup: Gateway, none 'available' for inet, use the first one configured. 'WAN_PPPOE' Jun 8 11:22:14 fw php[430]: rc.bootup: Gateway, none 'available' for inet6, use the first one configured. '' Jun 8 11:22:14 fw php[430]: rc.bootup: sync unbound done. Jun 8 11:22:14 fw kernel: re1: link state changed to UP Jun 8 11:22:14 fw kernel: re0: link state changed to UP Jun 8 11:22:14 fw kernel: re0.201: link state changed to UP Jun 8 11:22:14 fw check_reload_status[408]: Linkup starting re1 Jun 8 11:22:14 fw check_reload_status[408]: Linkup starting re0 Jun 8 11:22:14 fw check_reload_status[408]: Linkup starting re0.201 Jun 8 11:22:19 fw ppp[9666]: [wan_link0] PPPoE connection timeout after 9 seconds Jun 8 11:22:19 fw ppp[9666]: [wan_link0] Link: DOWN event Jun 8 11:22:19 fw ppp[9666]: [wan_link0] LCP: Down event Jun 8 11:22:19 fw ppp[9666]: [wan_link0] Link: reconnection attempt 1 in 1 seconds Jun 8 11:22:20 fw ppp[9666]: [wan_link0] Link: reconnection attempt 1 Jun 8 11:22:20 fw ppp[9666]: [wan_link0] PPPoE: Connecting to '' Jun 8 11:22:22 fw ppp[9666]: PPPoE: rec'd ACNAME "ptld-dsl-gw48.ptld.qwest.net" Jun 8 11:22:22 fw ppp[9666]: [wan_link0] PPPoE: connection successful Jun 8 11:22:22 fw ppp[9666]: [wan_link0] Link: UP event Jun 8 11:22:22 fw ppp[9666]: [wan_link0] LCP: Up event Jun 8 11:22:22 fw ppp[9666]: [wan_link0] LCP: state change Starting --> Req-Sent Jun 8 11:22:22 fw ppp[9666]: [wan_link0] LCP: SendConfigReq #1 Jun 8 11:22:22 fw ppp[9666]: [wan_link0] PROTOCOMP Jun 8 11:22:22 fw ppp[9666]: [wan_link0] MRU 1492 Jun 8 11:22:22 fw ppp[9666]: [wan_link0] MAGICNUM 0x9a65bebe Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: rec'd Configure Request #194 (Req-Sent) Jun 8 11:22:23 fw ppp[9666]: [wan_link0] MRU 1492 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] AUTHPROTO CHAP MD5 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] MAGICNUM 0x5ee2507e Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: SendConfigAck #194 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] MRU 1492 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] AUTHPROTO CHAP MD5 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] MAGICNUM 0x5ee2507e Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent) Jun 8 11:22:23 fw ppp[9666]: [wan_link0] PROTOCOMP Jun 8 11:22:23 fw ppp[9666]: [wan_link0] MRU 1492 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] MAGICNUM 0x9a65bebe Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: state change Ack-Sent --> Opened Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: LayerUp Jun 8 11:22:23 fw ppp[9666]: [wan_link0] CHAP: rec'd CHALLENGE #158 len: 42 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] Name: "JUNOS" Jun 8 11:22:23 fw ppp[9666]: [wan_link0] CHAP: Using authname "guildoforegonwoo@centurylink.net" Jun 8 11:22:23 fw ppp[9666]: [wan_link0] CHAP: sending RESPONSE #158 len: 53 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] CHAP: rec'd SUCCESS #158 len: 4 Jun 8 11:22:23 fw ppp[9666]: [wan_link0] LCP: authorization successful Jun 8 11:22:23 fw ppp[9666]: [wan_link0] Link: Matched action 'bundle "wan" ""' Jun 8 11:22:23 fw ppp[9666]: [wan_link0] Link: Join bundle "wan" Jun 8 11:22:23 fw ppp[9666]: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: Open event Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: state change Initial --> Starting Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: LayerStart Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: Up event Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: state change Starting --> Req-Sent Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: SendConfigReq #1 Jun 8 11:22:23 fw ppp[9666]: [wan] IPADDR 0.0.0.0 Jun 8 11:22:23 fw ppp[9666]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 8 11:22:23 fw ppp[9666]: [wan] PRIDNS 0.0.0.0 Jun 8 11:22:23 fw ppp[9666]: [wan] SECDNS 0.0.0.0 Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: rec'd Configure Request #92 (Req-Sent) Jun 8 11:22:23 fw ppp[9666]: [wan] IPADDR 207.225.84.48 Jun 8 11:22:23 fw ppp[9666]: [wan] 207.225.84.48 is OK Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: SendConfigAck #92 Jun 8 11:22:23 fw ppp[9666]: [wan] IPADDR 207.225.84.48 Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: state change Req-Sent --> Ack-Sent Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Jun 8 11:22:23 fw ppp[9666]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: SendConfigReq #2 Jun 8 11:22:23 fw ppp[9666]: [wan] IPADDR 0.0.0.0 Jun 8 11:22:23 fw ppp[9666]: [wan] PRIDNS 0.0.0.0 Jun 8 11:22:23 fw ppp[9666]: [wan] SECDNS 0.0.0.0 Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Jun 8 11:22:23 fw ppp[9666]: [wan] IPADDR 97.120.205.202 Jun 8 11:22:23 fw ppp[9666]: [wan] 97.120.205.202 is OK Jun 8 11:22:23 fw ppp[9666]: [wan] PRIDNS 205.171.3.65 Jun 8 11:22:23 fw ppp[9666]: [wan] SECDNS 205.171.2.65 Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: SendConfigReq #3 Jun 8 11:22:23 fw ppp[9666]: [wan] IPADDR 97.120.205.202 Jun 8 11:22:23 fw ppp[9666]: [wan] PRIDNS 205.171.3.65 Jun 8 11:22:23 fw ppp[9666]: [wan] SECDNS 205.171.2.65 Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Jun 8 11:22:23 fw ppp[9666]: [wan] IPADDR 97.120.205.202 Jun 8 11:22:23 fw ppp[9666]: [wan] PRIDNS 205.171.3.65 Jun 8 11:22:23 fw ppp[9666]: [wan] SECDNS 205.171.2.65 Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: state change Ack-Sent --> Opened Jun 8 11:22:23 fw ppp[9666]: [wan] IPCP: LayerUp Jun 8 11:22:23 fw ppp[9666]: [wan] 97.120.205.202 -> 207.225.84.48 Jun 8 11:22:23 fw check_reload_status[408]: Rewriting resolv.conf Jun 8 11:22:24 fw check_reload_status[408]: rc.newwanip starting pppoe1 Jun 8 11:22:24 fw ppp[9666]: [wan] IFACE: Up event Jun 8 11:22:24 fw ppp[9666]: [wan] IFACE: Rename interface ng0 to pppoe1 Jun 8 11:22:24 fw ppp[9666]: [wan] IFACE: Add description "WAN"
-
@jhg-goow said in Troubleshooting CenturyLink PPPoE Connection Drop:
Jun 8 03:38:07 fw kernel: re0: watchdog timeout
When you see that you need to try using the alternative Realtek driver.
Or better use some NIC other then Realtek if you can.
This is probably not a PPPoE problem but in fact the Realtek NIC/driver hanging.
Steve
-
@stephenw10 Thanks for pointing that out. I think you're right, RealTek seems to be non-commercial-grade.
The problems started when we enabled CloudSync to Google Drive from a local NAS. The crashes started happening just after 3 AM when the NAS does its sync to Google.
I've throttled CloudSync to a max of 10Mbps (1M bytes/sec) to confirm that this is the issue.
I'm also looking at a Protectli VP2410 to replace the Minisforum GK41 we're currently using. The Protectli has Intel NICs.
-
Intel NICs are the way to go if you have a choice.
Until then using the alternative Realtek driver may well prevent this happening.
Steve
-
@stephenw10 I've had a look through the lenghy post Updated Realtek NIC drivers missing in PfSense 2.6.0 . I notice there are several sets of instructions. Is there a canonical set of instructions on how to install the alternate driver without messing anything up?
I'm tempted to just go ahead and get new hardware with Intel NICs, it's not that big an expense.
-
At the command line run:
pkg-static add https://pkg.freebsd.org/FreeBSD:12:amd64/release_4/All/realtek-re-kmod-197.00.pkg
Then run:
echo 'if_re_load="YES"' >> /boot/loader.conf.local echo 'if_re_name="/boot/modules/if_re.ko"' >> /boot/loader.conf.local
Then reboot.
Check the boot logs to be sure the 1.97 driver version is loaded.
Steve