Pppoe unstable

I updated my Linksys WRT1900ACS to OpenWrt 19.07.2 r10947-65030d81f3 and am finding the pppoe WAN connection to be unstable. Every hour or two it seems to hang up and reconnect.

Looking at the Advanced Settings of that WAN interface the LCP echo failure threshold
is set 0 (default) which seems to mean that the parameter should be ignored.

I notice at the top of the following block of the system log at the time of the disconnection is the line:

daemon.info pppd[1916]: No response to 5 echo-requests

Any suggestions how to get better reliability in the connection?

System log extract

Fri May  1 18:08:03 2020 daemon.info pppd[1916]: No response to 5 echo-requests
Fri May  1 18:08:03 2020 daemon.notice pppd[1916]: Serial link appears to be disconnected.
Fri May  1 18:08:03 2020 daemon.info pppd[1916]: Connect time 148.0 minutes.
Fri May  1 18:08:03 2020 daemon.info pppd[1916]: Sent 34313208 bytes, received 653544843 bytes.
Fri May  1 18:08:03 2020 daemon.notice netifd: Network device 'pppoe-wan6' link is down
Fri May  1 18:08:03 2020 daemon.notice netifd: Network alias 'pppoe-wan6' link is down
Fri May  1 18:08:03 2020 daemon.notice netifd: Interface 'wan6_6' has link connectivity loss
Fri May  1 18:08:03 2020 daemon.err odhcp6c[2744]: Failed to send RS (Permission denied)
Fri May  1 18:08:03 2020 daemon.err odhcp6c[2744]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)
Fri May  1 18:08:03 2020 daemon.info pppd[1867]: No response to 5 echo-requests
Fri May  1 18:08:03 2020 daemon.notice pppd[1867]: Serial link appears to be disconnected.
Fri May  1 18:08:03 2020 daemon.info pppd[1867]: Connect time 148.0 minutes.
Fri May  1 18:08:03 2020 daemon.info pppd[1867]: Sent 0 bytes, received 47694 bytes.
Fri May  1 18:08:03 2020 daemon.notice netifd: Network device 'pppoe-wan' link is down
Fri May  1 18:08:03 2020 daemon.notice netifd: Interface 'wan6' has lost the connection
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: reading /tmp/resolv.conf.auto
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain test
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain onion
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain localhost
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain local
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain invalid
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain bind
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain lan
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:03 2020 daemon.notice netifd: wan6_6 (2744): Command failed: Permission denied
Fri May  1 18:08:03 2020 daemon.notice netifd: Interface 'wan' has lost the connection
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: reading /tmp/resolv.conf.auto
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain test
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain onion
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain localhost
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain local
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain invalid
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain bind
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using local addresses only for domain lan
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:03 2020 daemon.err odhcp6c[2744]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)
Fri May  1 18:08:03 2020 daemon.notice netifd: Interface 'wan6_6' is now down
Fri May  1 18:08:03 2020 daemon.notice netifd: Interface 'wan6_6' is disabled
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: read /etc/hosts - 4 addresses
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: read /tmp/hosts/odhcpd - 3 addresses
Fri May  1 18:08:03 2020 daemon.info dnsmasq[3540]: read /tmp/hosts/dhcp.cfg01411c - 17 addresses
Fri May  1 18:08:03 2020 daemon.info dnsmasq-dhcp[3540]: read /etc/ethers - 0 addresses
Fri May  1 18:08:04 2020 kern.debug kernel: [ 8892.759156] ieee80211 phy0: Mac80211 start BA f4:06:69:19:da:61
Fri May  1 18:08:05 2020 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED d0:13:fd:3c:c7:5f
Fri May  1 18:08:08 2020 daemon.info hostapd: wlan0: STA d0:13:fd:3c:c7:5f IEEE 802.11: authenticated
Fri May  1 18:08:08 2020 daemon.info hostapd: wlan0: STA d0:13:fd:3c:c7:5f IEEE 802.11: associated (aid 4)
Fri May  1 18:08:08 2020 daemon.notice hostapd: wlan0: AP-STA-CONNECTED d0:13:fd:3c:c7:5f
Fri May  1 18:08:08 2020 daemon.info hostapd: wlan0: STA d0:13:fd:3c:c7:5f WPA: pairwise key handshake completed (RSN)
Fri May  1 18:08:08 2020 daemon.info dnsmasq-dhcp[3540]: DHCPDISCOVER(br-lan) d0:13:fd:3c:c7:5f
Fri May  1 18:08:08 2020 daemon.info dnsmasq-dhcp[3540]: DHCPOFFER(br-lan) 192.168.1.158 d0:13:fd:3c:c7:5f
Fri May  1 18:08:08 2020 daemon.info dnsmasq-dhcp[3540]: DHCPREQUEST(br-lan) 192.168.1.158 d0:13:fd:3c:c7:5f
Fri May  1 18:08:08 2020 daemon.info dnsmasq-dhcp[3540]: DHCPACK(br-lan) 192.168.1.158 d0:13:fd:3c:c7:5f RosaliePhone
Fri May  1 18:08:09 2020 daemon.notice pppd[1916]: Connection terminated.
Fri May  1 18:08:09 2020 daemon.notice pppd[1867]: Connection terminated.
Fri May  1 18:08:09 2020 daemon.info pppd[1916]: Sent PADT
Fri May  1 18:08:09 2020 daemon.notice pppd[1916]: Modem hangup
Fri May  1 18:08:09 2020 daemon.info pppd[1867]: Sent PADT
Fri May  1 18:08:09 2020 daemon.info pppd[1916]: Exit.
Fri May  1 18:08:09 2020 daemon.notice netifd: Interface 'wan6' is now down
Fri May  1 18:08:09 2020 daemon.notice netifd: Interface 'wan6' is setting up now
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - slhc
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - ppp_generic
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - pppox
Fri May  1 18:08:09 2020 daemon.notice pppd[1867]: Modem hangup
Fri May  1 18:08:09 2020 daemon.info pppd[1867]: Exit.
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - pppoe
Fri May  1 18:08:09 2020 daemon.info pppd[4501]: Plugin rp-pppoe.so loaded.
Fri May  1 18:08:09 2020 daemon.info pppd[4501]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri May  1 18:08:09 2020 daemon.notice netifd: Interface 'wan' is now down
Fri May  1 18:08:09 2020 daemon.notice netifd: Interface 'wan' is setting up now
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - slhc
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - ppp_generic
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - pppox
Fri May  1 18:08:09 2020 daemon.err insmod: module is already loaded - pppoe
Fri May  1 18:08:09 2020 daemon.notice pppd[4501]: pppd 2.4.7 started by root, uid 0
Fri May  1 18:08:09 2020 daemon.info pppd[4518]: Plugin rp-pppoe.so loaded.
Fri May  1 18:08:09 2020 daemon.info pppd[4518]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri May  1 18:08:09 2020 daemon.notice pppd[4518]: pppd 2.4.7 started by root, uid 0
Fri May  1 18:08:24 2020 daemon.warn pppd[4501]: Timeout waiting for PADO packets
Fri May  1 18:08:24 2020 daemon.err pppd[4501]: Unable to complete PPPoE Discovery
Fri May  1 18:08:24 2020 daemon.info pppd[4501]: Exit.
Fri May  1 18:08:24 2020 daemon.notice netifd: Interface 'wan6' is now down
Fri May  1 18:08:24 2020 daemon.notice netifd: Interface 'wan6' is setting up now
Fri May  1 18:08:24 2020 daemon.warn pppd[4518]: Timeout waiting for PADO packets
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - slhc
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - ppp_generic
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - pppox
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - pppoe
Fri May  1 18:08:24 2020 daemon.info pppd[4571]: Plugin rp-pppoe.so loaded.
Fri May  1 18:08:24 2020 daemon.info pppd[4571]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri May  1 18:08:24 2020 daemon.err pppd[4518]: Unable to complete PPPoE Discovery
Fri May  1 18:08:24 2020 daemon.info pppd[4518]: Exit.
Fri May  1 18:08:24 2020 daemon.notice netifd: Interface 'wan' is now down
Fri May  1 18:08:24 2020 daemon.notice netifd: Interface 'wan' is setting up now
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - slhc
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - ppp_generic
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - pppox
Fri May  1 18:08:24 2020 daemon.err insmod: module is already loaded - pppoe
Fri May  1 18:08:24 2020 daemon.notice pppd[4571]: pppd 2.4.7 started by root, uid 0
Fri May  1 18:08:24 2020 daemon.info pppd[4594]: Plugin rp-pppoe.so loaded.
Fri May  1 18:08:24 2020 daemon.info pppd[4594]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri May  1 18:08:24 2020 daemon.notice pppd[4594]: pppd 2.4.7 started by root, uid 0
Fri May  1 18:08:39 2020 daemon.warn pppd[4571]: Timeout waiting for PADO packets
Fri May  1 18:08:39 2020 daemon.err pppd[4571]: Unable to complete PPPoE Discovery
Fri May  1 18:08:39 2020 daemon.info pppd[4571]: Exit.
Fri May  1 18:08:39 2020 daemon.notice netifd: Interface 'wan6' is now down
Fri May  1 18:08:39 2020 daemon.notice netifd: Interface 'wan6' is setting up now
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - slhc
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - ppp_generic
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - pppox
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - pppoe
Fri May  1 18:08:39 2020 daemon.warn pppd[4594]: Timeout waiting for PADO packets
Fri May  1 18:08:39 2020 daemon.info pppd[4647]: Plugin rp-pppoe.so loaded.
Fri May  1 18:08:39 2020 daemon.info pppd[4647]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri May  1 18:08:39 2020 daemon.err pppd[4594]: Unable to complete PPPoE Discovery
Fri May  1 18:08:39 2020 daemon.info pppd[4594]: Exit.
Fri May  1 18:08:39 2020 daemon.notice netifd: Interface 'wan' is now down
Fri May  1 18:08:39 2020 daemon.notice netifd: Interface 'wan' is setting up now
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - slhc
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - ppp_generic
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - pppox
Fri May  1 18:08:39 2020 daemon.err insmod: module is already loaded - pppoe
Fri May  1 18:08:39 2020 daemon.notice pppd[4647]: pppd 2.4.7 started by root, uid 0
Fri May  1 18:08:39 2020 daemon.info pppd[4670]: Plugin rp-pppoe.so loaded.
Fri May  1 18:08:39 2020 daemon.info pppd[4670]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri May  1 18:08:39 2020 daemon.info pppd[4647]: PPP session is 30584
Fri May  1 18:08:39 2020 daemon.warn pppd[4647]: Connected to 00:b7:71:16:e5:54 via interface eth1.2
Fri May  1 18:08:39 2020 kern.info kernel: [ 8927.754789] pppoe-wan6: renamed from ppp0
Fri May  1 18:08:39 2020 daemon.notice pppd[4670]: pppd 2.4.7 started by root, uid 0
Fri May  1 18:08:39 2020 daemon.info pppd[4647]: Renamed interface ppp0 to pppoe-wan6
Fri May  1 18:08:39 2020 daemon.info pppd[4647]: Using interface pppoe-wan6
Fri May  1 18:08:39 2020 daemon.notice pppd[4647]: Connect: pppoe-wan6 <--> eth1.2
Fri May  1 18:08:39 2020 daemon.info pppd[4670]: PPP session is 54665
Fri May  1 18:08:39 2020 daemon.warn pppd[4670]: Connected to 00:2a:10:ce:0e:d6 via interface eth1.2
Fri May  1 18:08:39 2020 kern.info kernel: [ 8927.835152] pppoe-wan: renamed from ppp1
Fri May  1 18:08:39 2020 daemon.info pppd[4670]: Renamed interface ppp1 to pppoe-wan
Fri May  1 18:08:39 2020 daemon.info pppd[4670]: Using interface pppoe-wan
Fri May  1 18:08:39 2020 daemon.notice pppd[4670]: Connect: pppoe-wan <--> eth1.2
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: PAP authentication succeeded
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: peer from calling number 00:B7:71:16:E5:54 authorized
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: local  LL address fe80::5123:ca9b:af60:95b7
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: remote LL address fe80::02b7:71ff:fe16:e480
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: local  IP address 193.115.101.133
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: remote IP address 10.20.22.35
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: primary   DNS address 203.12.160.35
Fri May  1 18:08:40 2020 daemon.notice pppd[4647]: secondary DNS address 203.12.160.36
Fri May  1 18:08:40 2020 daemon.notice netifd: Network device 'pppoe-wan6' link is up
Fri May  1 18:08:40 2020 daemon.notice netifd: Interface 'wan6' is now up
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: reading /tmp/resolv.conf.auto
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain test
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain onion
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain localhost
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain local
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain invalid
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain bind
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain lan
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 2606:4700:4700::1111#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 2606:4700:4700::1001#53
Fri May  1 18:08:40 2020 daemon.notice netifd: Network alias 'pppoe-wan6' link is up
Fri May  1 18:08:40 2020 daemon.notice netifd: Interface 'wan6_6' is enabled
Fri May  1 18:08:40 2020 daemon.notice netifd: Interface 'wan6_6' has link connectivity
Fri May  1 18:08:40 2020 daemon.notice netifd: Interface 'wan6_6' is setting up now
Fri May  1 18:08:40 2020 user.notice firewall: Reloading firewall due to ifup of wan6 (pppoe-wan6)
Fri May  1 18:08:40 2020 daemon.notice pppd[4670]: PAP authentication succeeded
Fri May  1 18:08:40 2020 daemon.notice pppd[4670]: peer from calling number 00:2A:10:CE:0E:D6 authorized
Fri May  1 18:08:40 2020 daemon.notice pppd[4670]: local  IP address 61.68.201.58
Fri May  1 18:08:40 2020 daemon.notice pppd[4670]: remote IP address 10.20.25.50
Fri May  1 18:08:40 2020 daemon.notice pppd[4670]: primary   DNS address 203.12.160.35
Fri May  1 18:08:40 2020 daemon.notice pppd[4670]: secondary DNS address 203.12.160.36
Fri May  1 18:08:40 2020 daemon.notice netifd: Network device 'pppoe-wan' link is up
Fri May  1 18:08:40 2020 daemon.notice netifd: Interface 'wan' is now up
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: reading /tmp/resolv.conf.auto
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain test
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain onion
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain localhost
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain local
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain invalid
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain bind
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using local addresses only for domain lan
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.1.1.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 1.0.0.1#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 2606:4700:4700::1111#53
Fri May  1 18:08:40 2020 daemon.info dnsmasq[3540]: using nameserver 2606:4700:4700::1001#53
Fri May  1 18:08:40 2020 user.notice firewall: Reloading firewall due to ifupdate of wan6 (pppoe-wan6)
Fri May  1 18:08:40 2020 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Fri May  1 18:08:42 2020 daemon.notice netifd: Interface 'wan6_6' is now up
...

I may have overdone it but I increased the LCP echo failure threshold to 500 with the LCP echo interval = 5 seconds and the connection now seems stable.

Feedback welcome.

1 Like

Known issue/bug since LEDE 17. Set the 'threshold' value to '5' should work well.

https://forum.openwrt.org/t/pppoe-on-wan-gets-down-randomly-19-07-2/61495

1 Like

Thanks for that. I've backed those settings off to 5 @ 5 and the connection is staying up. :smile:

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.