Here are logs for one that just happened. This has a different listing as it starts with LCP terminated by peer.
pppd.log
Mar 13 15:28:29 bluetongue pppd[14577]: LCP terminated by peer
Mar 13 15:28:29 bluetongue pppd[14577]: Connect time 2393.1 minutes.
Mar 13 15:28:29 bluetongue pppd[14577]: Sent 0 bytes, received 945838052 bytes.
Mar 13 15:28:29 bluetongue pppd[14577]: Modem hangup
Mar 13 15:28:29 bluetongue pppd[14577]: Connection terminated.
Mar 13 15:28:29 bluetongue pppd[14577]: Sent PADT
Mar 13 15:28:29 bluetongue pppd[14577]: Exit.
Mar 13 15:28:29 bluetongue pppd[7445]: Plugin pppoe.so loaded.
Mar 13 15:28:29 bluetongue pppd[7445]: PPPoE plugin from pppd 2.5.1
Mar 13 15:28:29 bluetongue pppd[7445]: pppd 2.5.1 started by root, uid 0
Mar 13 15:28:29 bluetongue pppd[7445]: PPP session is 6444
Mar 13 15:28:29 bluetongue pppd[7445]: Connected to ##.##.##.##.##.## via interface wan.2
Mar 13 15:28:29 bluetongue pppd[7445]: Using interface pppoe-wan
Mar 13 15:28:29 bluetongue pppd[7445]: Connect: pppoe-wan <--> wan.2
Mar 13 15:28:30 bluetongue pppd[7445]: PAP authentication succeeded
Mar 13 15:28:30 bluetongue pppd[7445]: peer from calling number 40:14:82:A1:3B:D4 authorized
Mar 13 15:28:30 bluetongue pppd[7445]: local LL address fe80::8cb2:5409:f491:cd4e
Mar 13 15:28:30 bluetongue pppd[7445]: remote LL address fe80::4214:82ff:fea1:3b00
Mar 13 15:28:30 bluetongue pppd[7445]: local IP address ###.###.###.###
Mar 13 15:28:30 bluetongue pppd[7445]: remote IP address ###.###.###.###
Mar 13 15:28:30 bluetongue pppd[7445]: primary DNS address ###.###.###.###
Mar 13 15:28:30 bluetongue pppd[7445]: secondary DNS address ###.###.###.###
netifd.log
Mar 13 15:28:29 bluetongue netifd: Interface 'wan_6' is disabled
Mar 13 15:28:29 bluetongue netifd: Network device 'pppoe-wan' link is down
Mar 13 15:28:29 bluetongue netifd: Network alias 'pppoe-wan' link is down
Mar 13 15:28:29 bluetongue netifd: Interface 'wan_6' has link connectivity loss
Mar 13 15:28:29 bluetongue netifd: Interface 'wan' has lost the connection
Mar 13 15:28:29 bluetongue netifd: wan_6 (14638): Command failed: ubus call network.interface notify_proto { "action": 0, "link-up": false, "keep": false, "interface": "wan_6" } (Permission denied)
Mar 13 15:28:29 bluetongue netifd: Interface 'wan' is now down
Mar 13 15:28:29 bluetongue netifd: Interface 'wan' is setting up now
Mar 13 15:28:29 bluetongue netifd: Interface 'wan_6' is now down
Mar 13 15:28:30 bluetongue netifd: Network device 'pppoe-wan' link is up
Mar 13 15:28:30 bluetongue netifd: Network alias 'pppoe-wan' link is up
Mar 13 15:28:30 bluetongue netifd: Interface 'wan' is now up
Mar 13 15:28:30 bluetongue netifd: Interface 'wan_6' is enabled
Mar 13 15:28:30 bluetongue netifd: Interface 'wan_6' has link connectivity
Mar 13 15:28:30 bluetongue netifd: Interface 'wan_6' is setting up now
Mar 13 15:28:34 bluetongue netifd: Interface 'wan_6' is now up
This is the other side ending the pppoe connection as it should be done...
My ISP does that every 24 hours... but that is different from the other ones...
This is your PPPoE client giving up after 5 attempts to talk to the remote end...
Maybe it is time to try again to increase the number of tries and/or duration between attempts and see whether you can huddle through these transient blockages... (it would be great though to figure out the root cause of those)
So, if I see LCP terminated by peer then I'm not looking at a fault, rather, for some reason my ISP is cycling the connection (if it comes up again).
In the other cases is it fair to conclude an error is occurring somewhere but we can't say where? I guess possible candidate locations are my router, the ISP's network connection box/bridge/modem, the twisted pair snaking up the street to the kerbside pit or anyway else upstream to the ISP' end of the pppoe connection.
It doesn't seem like there's a good prospect of tracking down this problem. Other than continuing to tinker with the keepalive settings, is there any other diagnositic approach I could try? (I've tried changing the logging level to debug without any apparent effect.)
That is at least my interpretation, however the reason for the ISP side to do that could technically be some sort of fault as well, but I guess that is maybe too many levels of indirection
As far as I understand the ppp log alone is unlikely to tell us where. But if e.g. these events correlate with the physical wan device going down this at least implies some connection between the two.
That is the first I would try, if only to learn how long these events take. Note however you can try to keep alive a connection without traffic for as long as you like, unless your ISP does as well you might have to go through a pppoe reconnection...
I've upped the keepalive settings again without much luck.
Looking at the openwrt.log in the root directory of the device I see the following :
Tue Mar 18 20:20:33 2025 kern.info kernel: [624967.235200] mv88e6085 f1072004.mdio-mii:00 wan: Link is Down
Tue Mar 18 20:20:33 2025 daemon.notice netifd: Network device 'wan' link is down
Tue Mar 18 20:20:33 2025 daemon.notice netifd: 8021q 'wan.2' link is down
Tue Mar 18 20:20:33 2025 daemon.notice netifd: Interface 'wan' has link connectivity loss
Tue Mar 18 20:20:33 2025 daemon.info pppd[20730]: Terminating on signal 15
Tue Mar 18 20:20:33 2025 daemon.info pppd[20730]: Connect time 2779.6 minutes.
Tue Mar 18 20:20:33 2025 daemon.info pppd[20730]: Sent 0 bytes, received 1006879380 bytes.
Tue Mar 18 20:20:33 2025 daemon.err odhcp6c[20795]: Failed to send RS (Network unreachable)
Tue Mar 18 20:20:33 2025 daemon.err odhcp6c[20795]: Failed to send RELEASE message to ff02::1:2 (Network unreachable)
Tue Mar 18 20:20:33 2025 daemon.notice netifd: Interface 'wan_6' is disabled
Tue Mar 18 20:20:33 2025 daemon.notice netifd: Network device 'pppoe-wan' link is down
Tue Mar 18 20:20:33 2025 daemon.notice netifd: Network alias 'pppoe-wan' link is down
Tue Mar 18 20:20:33 2025 daemon.notice netifd: Interface 'wan_6' has link connectivity loss
Tue Mar 18 20:20:33 2025 daemon.notice netifd: wan_6 (20795): Command failed: ubus call network.interface notify_proto { "action": 0, "link-up": false, "keep": false, "interface": "wan_6" } (Permission denied)
Tue Mar 18 20:20:33 2025 daemon.err odhcp6c[20795]: Failed to send SOLICIT message to ff02::1:2 (Network unreachable)
Tue Mar 18 20:20:33 2025 daemon.notice netifd: Interface 'wan_6' is now down
Tue Mar 18 20:20:33 2025 daemon.info dnsmasq[1]: read /etc/hosts - 12 names
Tue Mar 18 20:20:33 2025 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg01411c - 8 names
Tue Mar 18 20:20:33 2025 daemon.info dnsmasq[1]: read /tmp/hosts/odhcpd - 8 names
Tue Mar 18 20:20:33 2025 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses
Tue Mar 18 20:20:34 2025 daemon.warn odhcpd[1872]: No default route present, overriding ra_lifetime to 0!
Tue Mar 18 20:20:38 2025 daemon.notice netifd: Interface 'wan' is now down
Tue Mar 18 20:21:27 2025 daemon.notice hostapd: phy0-ap0: AP-STA-DISCONNECTED ##:##:##:##:##:##
Tue Mar 18 20:21:28 2025 daemon.info hostapd: phy0-ap0: STA ##:##:##:##:##:## IEEE 802.11: authenticated
Tue Mar 18 20:21:28 2025 daemon.info hostapd: phy0-ap0: STA ##:##:##:##:##:## IEEE 802.11: associated (aid 7)
Tue Mar 18 20:21:28 2025 daemon.notice hostapd: phy0-ap0: AP-STA-CONNECTED ##:##:##:##:##:## auth_alg=open
Tue Mar 18 20:21:28 2025 daemon.info hostapd: phy0-ap0: STA ##:##:##:##:##:## WPA: pairwise key handshake completed (RSN)
Tue Mar 18 20:21:28 2025 daemon.notice hostapd: phy0-ap0: EAPOL-4WAY-HS-COMPLETED ##:##:##:##:##:##
Tue Mar 18 20:21:28 2025 daemon.warn odhcpd[1872]: No default route present, overriding ra_lifetime to 0!
Tue Mar 18 20:21:29 2025 daemon.warn odhcpd[1872]: No default route present, overriding ra_lifetime to 0!
Tue Mar 18 20:21:30 2025 daemon.warn odhcpd[1872]: No default route present, overriding ra_lifetime to 0!
Tue Mar 18 20:21:34 2025 daemon.info dnsmasq[1]: read /etc/hosts - 12 names
Tue Mar 18 20:21:34 2025 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg01411c - 8 names
Tue Mar 18 20:21:34 2025 daemon.info dnsmasq[1]: read /tmp/hosts/odhcpd - 6 names
Tue Mar 18 20:21:34 2025 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses
Tue Mar 18 20:21:35 2025 daemon.info dnsmasq[1]: read /etc/hosts - 12 names
Tue Mar 18 20:21:35 2025 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg01411c - 8 names
Tue Mar 18 20:21:35 2025 daemon.info dnsmasq[1]: read /tmp/hosts/odhcpd - 8 names
Tue Mar 18 20:21:35 2025 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses
Tue Mar 18 20:21:38 2025 daemon.notice netifd: Network device 'wan' link is up
Tue Mar 18 20:21:38 2025 daemon.notice netifd: 8021q 'wan.2' link is up
Tue Mar 18 20:21:38 2025 daemon.notice netifd: Interface 'wan' has link connectivity
Tue Mar 18 20:21:38 2025 daemon.notice netifd: Interface 'wan' is setting up now
Tue Mar 18 20:21:38 2025 kern.info kernel: [625032.589047] mv88e6085 f1072004.mdio-mii:00 wan: Link is Up - 1Gbps/Full - flow control off
Tue Mar 18 20:21:38 2025 daemon.info pppd[5924]: Plugin pppoe.so loaded.
Tue Mar 18 20:21:38 2025 daemon.info pppd[5924]: PPPoE plugin from pppd 2.5.1
Tue Mar 18 20:21:38 2025 daemon.notice pppd[5924]: pppd 2.5.1 started by root, uid 0
Tue Mar 18 20:21:43 2025 daemon.notice hostapd: phy0-ap0: AP-STA-DISCONNECTED ##:##:##:##:##:##
Tue Mar 18 20:21:44 2025 daemon.info pppd[5924]: PPP session is 15593
Tue Mar 18 20:21:44 2025 daemon.warn pppd[5924]: Connected to ##:##:##:##:##:## via interface wan.2
Tue Mar 18 20:21:44 2025 daemon.info pppd[5924]: Using interface pppoe-wan
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: Connect: pppoe-wan <--> wan.2
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: PAP authentication succeeded
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: peer from calling number ##:##:##:##:##:## authorized
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: local LL address ####::####:####:####:####
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: remote LL address ####::####:####:####:####
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: local IP address ##.##.##.##
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: remote IP address ##.##.##.##
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: primary DNS address ##.##.##.##
Tue Mar 18 20:21:44 2025 daemon.notice pppd[5924]: secondary DNS address ##.##.##.##
Tue Mar 18 20:21:44 2025 daemon.notice netifd: Network device 'pppoe-wan' link is up
Tue Mar 18 20:21:44 2025 daemon.notice netifd: Network alias 'pppoe-wan' link is up
Tue Mar 18 20:21:44 2025 daemon.notice netifd: Interface 'wan' is now up
Tue Mar 18 20:21:44 2025 daemon.notice netifd: Interface 'wan_6' is enabled
Tue Mar 18 20:21:44 2025 daemon.notice netifd: Interface 'wan_6' has link connectivity
Tue Mar 18 20:21:44 2025 daemon.notice netifd: Interface 'wan_6' is setting up now
Tue Mar 18 20:21:44 2025 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Tue Mar 18 20:21:45 2025 user.notice firewall: Reloading firewall due to ifupdate of wan (pppoe-wan)
Tue Mar 18 20:21:48 2025 daemon.notice netifd: Interface 'wan_6' is now up
Tue Mar 18 20:21:48 2025 daemon.info dnsmasq[1]: read /etc/hosts - 12 names
Tue Mar 18 20:21:48 2025 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg01411c - 8 names
Tue Mar 18 20:21:48 2025 daemon.info dnsmasq[1]: read /tmp/hosts/odhcpd - 16 names
Tue Mar 18 20:21:48 2025 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses
Tue Mar 18 20:21:48 2025 user.notice firewall: Reloading firewall due to ifup of wan_6 (pppoe-wan)
That log listing seems to combine the various other logs together and I note that the first sign of trouble seems to be: mv88e6085 f1072004.mdio-mii:00 wan: Link is Down
Well if that interface is flapping than all traffic over that interface is affected negtively including a PPPoE tunnel... So why is that happening and why is option force_link '1' not helping...
