PPPoE disconnect itself

OpenWrt 23.05-rc3's PPPoE disconnects itself.
machine: J4125, VMware ESXi 8.0.0
logs:

Fri Aug  4 18:16:52 2023 daemon.info pppd[2399]: No response to 5 echo-requests
Fri Aug  4 18:16:52 2023 daemon.notice pppd[2399]: Serial link appears to be disconnected.
Fri Aug  4 18:16:52 2023 daemon.info pppd[2399]: Connect time 536.4 minutes.
Fri Aug  4 18:16:52 2023 daemon.info pppd[2399]: Sent 500448376 bytes, received 2591356030 bytes.
Fri Aug  4 18:16:52 2023 daemon.notice netifd: Network device 'pppoe-wan' link is down
Fri Aug  4 18:16:52 2023 daemon.err odhcp6c[3208]: Failed to send RS (Network unreachable)
Fri Aug  4 18:16:52 2023 daemon.notice netifd: Network alias 'pppoe-wan' link is down
Fri Aug  4 18:16:52 2023 daemon.notice netifd: Interface 'wan_6' has link connectivity loss
Fri Aug  4 18:16:52 2023 daemon.err odhcp6c[3208]: Failed to send RELEASE message to ff02::1:2 (Network unreachable)
Fri Aug  4 18:16:52 2023 daemon.notice netifd: Interface 'wan' has lost the connection
Fri Aug  4 18:16:52 2023 daemon.notice netifd: Interface 'wan_6' is disabled
Fri Aug  4 18:16:52 2023 daemon.notice netifd: wan_6 (3208): Command failed: ubus call network.interface notify_proto { "action": 0, "link-up": false, "keep": false, "interface": "wan_6" } (Permission denied)
Fri Aug  4 18:16:52 2023 daemon.err odhcp6c[3208]: Failed to send SOLICIT message to ff02::1:2 (Network unreachable)
Fri Aug  4 18:16:52 2023 daemon.notice netifd: Interface 'wan_6' is now down
Fri Aug  4 18:16:53 2023 daemon.warn odhcpd[2256]: No default route present, overriding ra_lifetime!
Fri Aug  4 18:16:58 2023 daemon.notice pppd[2399]: Connection terminated.
Fri Aug  4 18:16:58 2023 daemon.info pppd[2399]: Connect time 536.4 minutes.
Fri Aug  4 18:16:58 2023 daemon.info pppd[2399]: Sent 500448376 bytes, received 2591356030 bytes.
Fri Aug  4 18:16:58 2023 daemon.notice pppd[2399]: Modem hangup
Fri Aug  4 18:16:58 2023 daemon.info pppd[2399]: Exit.
Fri Aug  4 18:16:58 2023 daemon.notice netifd: Interface 'wan' is now down
Fri Aug  4 18:16:58 2023 daemon.notice netifd: Interface 'wan' is disabled
Fri Aug  4 18:16:58 2023 daemon.notice netifd: Interface 'wan' is enabled
Fri Aug  4 18:16:58 2023 daemon.notice netifd: Interface 'wan' is setting up now
Fri Aug  4 18:16:58 2023 kern.info kernel: [32197.836796] vmxnet3 0000:13:00.0 eth1: intr type 3, mode 0, 5 vectors allocated
Fri Aug  4 18:16:58 2023 kern.info kernel: [32197.837818] vmxnet3 0000:13:00.0 eth1: NIC Link is Up 10000 Mbps
Fri Aug  4 18:16:58 2023 kern.info kernel: [32197.838097] 8021q: adding VLAN 0 to HW filter on device eth1
Fri Aug  4 18:16:58 2023 daemon.notice netifd: wan (9171): uci: Entry not found
Fri Aug  4 18:16:58 2023 daemon.notice netifd: wan (9171): sh: out of range
Fri Aug  4 18:16:58 2023 daemon.info pppd[9178]: Plugin pppoe.so loaded.
Fri Aug  4 18:16:58 2023 daemon.info pppd[9178]: PPPoE plugin from pppd 2.4.9
Fri Aug  4 18:16:58 2023 daemon.notice pppd[9178]: pppd 2.4.9 started by root, uid 0
Fri Aug  4 18:16:59 2023 daemon.warn odhcpd[2256]: No default route present, overriding ra_lifetime!
Fri Aug  4 18:16:59 2023 kern.info kernel: [32198.908697] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Fri Aug  4 18:17:09 2023 daemon.warn odhcpd[2256]: No default route present, overriding ra_lifetime!
Fri Aug  4 18:17:13 2023 daemon.warn pppd[9178]: Timeout waiting for PADS packets
Fri Aug  4 18:17:13 2023 daemon.err pppd[9178]: Unable to complete PPPoE Discovery
Fri Aug  4 18:17:13 2023 daemon.info pppd[9178]: Exit.
Fri Aug  4 18:17:13 2023 daemon.notice netifd: Interface 'wan' is now down
Fri Aug  4 18:17:13 2023 daemon.notice netifd: Interface 'wan' is disabled
Fri Aug  4 18:17:13 2023 daemon.notice netifd: Interface 'wan' is enabled
Fri Aug  4 18:17:13 2023 daemon.notice netifd: Interface 'wan' is setting up now
Fri Aug  4 18:17:13 2023 kern.info kernel: [32213.087361] vmxnet3 0000:13:00.0 eth1: intr type 3, mode 0, 5 vectors allocated
Fri Aug  4 18:17:13 2023 kern.info kernel: [32213.088025] vmxnet3 0000:13:00.0 eth1: NIC Link is Up 10000 Mbps
Fri Aug  4 18:17:13 2023 kern.info kernel: [32213.088239] 8021q: adding VLAN 0 to HW filter on device eth1
Fri Aug  4 18:17:13 2023 daemon.notice netifd: wan (9362): uci: Entry not found
Fri Aug  4 18:17:13 2023 daemon.notice netifd: wan (9362): sh: out of range
Fri Aug  4 18:17:13 2023 daemon.info pppd[9369]: Plugin pppoe.so loaded.
Fri Aug  4 18:17:13 2023 daemon.info pppd[9369]: PPPoE plugin from pppd 2.4.9
Fri Aug  4 18:17:13 2023 daemon.notice pppd[9369]: pppd 2.4.9 started by root, uid 0
Fri Aug  4 18:17:14 2023 daemon.warn odhcpd[2256]: No default route present, overriding ra_lifetime!
Fri Aug  4 18:17:14 2023 kern.info kernel: [32214.107223] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Fri Aug  4 18:17:19 2023 daemon.info pppd[9369]: PPP session is 8160
Fri Aug  4 18:17:19 2023 daemon.warn pppd[9369]: Connected to cc:cc:81:eb:7c:a7 via interface eth1
Fri Aug  4 18:17:19 2023 kern.info kernel: [32218.307429] pppoe-wan: renamed from ppp0
Fri Aug  4 18:17:19 2023 daemon.info pppd[9369]: Renamed interface ppp0 to pppoe-wan
Fri Aug  4 18:17:19 2023 daemon.info pppd[9369]: Using interface pppoe-wan
Fri Aug  4 18:17:19 2023 daemon.notice pppd[9369]: Connect: pppoe-wan <--> eth1
Fri Aug  4 18:17:25 2023 daemon.info pppd[9369]: syncppp not active
Fri Aug  4 18:17:25 2023 daemon.info pppd[9369]: Remote message: Authentication success,Welcome!
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: PAP authentication succeeded
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: peer from calling number CC:CC:81:EB:7C:A7 authorized
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: local  LL address fe80::b13b:ac19:8f01:402b
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: remote LL address fe80::cecc:81ff:feeb:7ca7
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: local  IP address xxx.xxx.xxx.xxx
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: remote IP address xxx.xxx.xxx.xxx
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: primary   DNS address xxx.xxx.xxx.xxx
Fri Aug  4 18:17:25 2023 daemon.notice pppd[9369]: secondary DNS address xxx.xxx.xxx.xxx
Fri Aug  4 18:17:25 2023 daemon.notice netifd: Network device 'pppoe-wan' link is up
Fri Aug  4 18:17:25 2023 daemon.notice netifd: Network alias 'pppoe-wan' link is up
Fri Aug  4 18:17:25 2023 daemon.notice netifd: Interface 'wan' is now up
Fri Aug  4 18:17:25 2023 daemon.notice netifd: Interface 'wan_6' is enabled
Fri Aug  4 18:17:25 2023 daemon.notice netifd: Interface 'wan_6' has link connectivity
Fri Aug  4 18:17:25 2023 daemon.notice netifd: Interface 'wan_6' is setting up now
Fri Aug  4 18:17:25 2023 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Fri Aug  4 18:17:25 2023 user.notice firewall: Reloading firewall due to ifupdate of wan (pppoe-wan)
Fri Aug  4 18:17:26 2023 daemon.warn odhcpd[2256]: No default route present, overriding ra_lifetime!
Fri Aug  4 18:17:31 2023 daemon.notice netifd: Interface 'wan_6' is now up
Fri Aug  4 18:17:31 2023 user.notice firewall: Reloading firewall due to ifup of wan_6 (pppoe-wan)
Fri Aug  4 18:17:40 2023 daemon.info pppd[9369]: No response to 5 echo-requests
Fri Aug  4 18:17:40 2023 daemon.notice pppd[9369]: Serial link appears to be disconnected.
Fri Aug  4 18:17:40 2023 daemon.info pppd[9369]: Connect time 0.3 minutes.
Fri Aug  4 18:17:40 2023 daemon.info pppd[9369]: Sent 388147 bytes, received 1818734 bytes.
Fri Aug  4 18:17:40 2023 daemon.err odhcp6c[9587]: Failed to send RS (Network unreachable)
Fri Aug  4 18:17:40 2023 daemon.notice netifd: Network device 'pppoe-wan' link is down
Fri Aug  4 18:17:40 2023 daemon.notice netifd: Network alias 'pppoe-wan' link is down
Fri Aug  4 18:17:40 2023 daemon.notice netifd: Interface 'wan_6' has link connectivity loss
Fri Aug  4 18:17:40 2023 daemon.err odhcp6c[9587]: Failed to send RELEASE message to ff02::1:2 (Network unreachable)
Fri Aug  4 18:17:40 2023 daemon.notice netifd: Interface 'wan' has lost the connection
Fri Aug  4 18:17:40 2023 daemon.notice netifd: Interface 'wan_6' is disabled
Fri Aug  4 18:17:40 2023 daemon.notice netifd: wan_6 (9587): Command failed: ubus call network.interface notify_proto { "action": 0, "link-up": false, "keep": false, "interface": "wan_6" } (Permission denied)
Fri Aug  4 18:17:40 2023 daemon.err odhcp6c[9587]: Failed to send SOLICIT message to ff02::1:2 (Network unreachable)
Fri Aug  4 18:17:40 2023 daemon.notice netifd: Interface 'wan_6' is now down
Fri Aug  4 18:17:41 2023 daemon.warn odhcpd[2256]: No default route present, overriding ra_lifetime!

The remote end of the PPPoE connection failed to reply to 5 echo-requests and since this is your configured limit the connection was considered disconnected. The question is why did the remote end not respond? Could be that the PPPoE tunnel was still fine and the remote end just is not very timely in responding (in which case increasing the lost probe threshold might help), or the connection might have been disconnected for other reasons. However I see no termination message from the remote end (which is how a PPPoE server tells a client that the connection was closed from the remote end). Maybe enable the debug option in IIRC /etc/ppp/options?

1 Like