Hi all,
I updated the firmware to 4.5.4 and the behavior I was seeing at the beginning is back. I leave the logs below - I have since rolled back to 4.5.3 and got PPPoE working again with no issue.
Something is happening here but is above my knowledge level. I noticed a difference in the interface and IPv6 being used to join mDNS multicast in the logs - maybe that is related to the issue. When the connection fails the router uses eth1.IPv6
, while when it succeeds it uses pppoe-wan.IPv6
with a different IPv6 address.
Fri Dec 15 12:37:48 2023 daemon.notice netifd: Network device 'eth1' link is up
Fri Dec 15 12:37:48 2023 daemon.notice netifd: VLAN 'eth1.10' link is up
Fri Dec 15 12:37:48 2023 daemon.notice netifd: Interface 'wan' has link connectivity
Fri Dec 15 12:37:48 2023 daemon.notice netifd: Interface 'wan' is setting up now
Fri Dec 15 12:37:48 2023 kern.info kernel: [65461.682707] mtk_soc_eth 15100000.ethernet eth1: Link is Up - 1Gbps/Full - flow control off
Fri Dec 15 12:37:48 2023 kern.info kernel: [65461.691007] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Fri Dec 15 12:37:48 2023 daemon.info pppd[2135]: Plugin pppoe.so loaded.
Fri Dec 15 12:37:48 2023 daemon.info pppd[2135]: PPPoE plugin from pppd 2.4.9
Fri Dec 15 12:37:49 2023 daemon.notice pppd[2135]: pppd 2.4.9 started by root, uid 0
Fri Dec 15 12:37:49 2023 daemon.info pppd[2135]: PPP session is 1
Fri Dec 15 12:37:49 2023 daemon.warn pppd[2135]: Connected to [Media_converter_MAC_add] via interface eth1.10
Fri Dec 15 12:37:49 2023 kern.info kernel: [65461.950670] pppoe-wan: renamed from ppp0
Fri Dec 15 12:37:49 2023 daemon.info pppd[2135]: Renamed interface ppp0 to pppoe-wan
Fri Dec 15 12:37:49 2023 daemon.info pppd[2135]: Using interface pppoe-wan
Fri Dec 15 12:37:49 2023 daemon.notice pppd[2135]: Connect: pppoe-wan <--> eth1.10
Fri Dec 15 12:37:50 2023 daemon.info avahi-daemon[5375]: Joining mDNS multicast group on interface eth1.IPv6 with address xxxx::xxxx:xxxx:xxxx:xxxx.
Fri Dec 15 12:37:50 2023 daemon.info avahi-daemon[5375]: New relevant interface eth1.IPv6 for mDNS.
Fri Dec 15 12:37:50 2023 daemon.info avahi-daemon[5375]: Registering new address record for xxxx::xxxx:xxxx:xxxx:xxxx on eth1.*.
Fri Dec 15 12:37:52 2023 daemon.info pppd[2135]: CHAP authentication succeeded: CHAP authentication success
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: CHAP authentication succeeded
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: peer from calling number [Media_converter_MAC_add] authorized
Fri Dec 15 12:37:52 2023 daemon.err pppd[2135]: sif6addr: ioctl(SIOCSIFADDR): Permission denied (line 3011)
Fri Dec 15 12:37:52 2023 daemon.warn pppd[2135]: cif6addr: ioctl(SIOCDIFADDR): No such address
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: local IP address YYY.YYY.YYY.YYY
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: remote IP address ZZZ.ZZZ.ZZZ.ZZZ
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: primary DNS address 195.238.2.21
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: secondary DNS address 195.238.2.22
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Joining mDNS multicast group on interface pppoe-wan.IPv4 with address YYY.YYY.YYY.YYY.
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: New relevant interface pppoe-wan.IPv4 for mDNS.
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Registering new address record for YYY.YYY.YYY.YYY on pppoe-wan.IPv4.
Fri Dec 15 12:37:52 2023 daemon.info pppd[2135]: LCP terminated by peer
Fri Dec 15 12:37:52 2023 daemon.info pppd[2135]: Connect time 0.0 minutes.
Fri Dec 15 12:37:52 2023 daemon.info pppd[2135]: Sent 0 bytes, received 4 bytes.
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Interface pppoe-wan.IPv4 no longer relevant for mDNS.
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Leaving mDNS multicast group on interface pppoe-wan.IPv4 with address YYY.YYY.YYY.YYY.
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Withdrawing address record for 80.200.150.76 on pppoe-wan.
Fri Dec 15 12:37:52 2023 daemon.notice netifd: Interface 'wan' is now up
Fri Dec 15 12:37:52 2023 daemon.notice netifd: Interface 'wan' has lost the connection
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: Modem hangup
Fri Dec 15 12:37:52 2023 daemon.notice pppd[2135]: Connection terminated.
Fri Dec 15 12:37:52 2023 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Fri Dec 15 12:37:52 2023 daemon.info pppd[2135]: Exit.
Fri Dec 15 12:37:52 2023 daemon.notice netifd: Interface 'wan' is now down
Fri Dec 15 12:37:52 2023 kern.info kernel: [65465.468638] mtk_soc_eth 15100000.ethernet eth1: Link is Down
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Interface eth1.IPv6 no longer relevant for mDNS.
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Leaving mDNS multicast group on interface eth1.IPv6 with address xxxx::xxxx:xxxx:xxxx:xxxx.
Fri Dec 15 12:37:52 2023 daemon.info avahi-daemon[5375]: Withdrawing address record for xxxx::xxxx:xxxx:xxxx:xxxx on eth1.
Fri Dec 15 12:37:52 2023 daemon.notice netifd: Interface 'wan' is disabled
Fri Dec 15 12:37:53 2023 kern.info kernel: [65465.887956] mtk_soc_eth 15100000.ethernet eth1: PHY [mdio-bus:01] driver [RTL8221B-VB-CG 2.5Gbps PHY] (irq=62)
Fri Dec 15 12:37:53 2023 kern.info kernel: [65465.898232] mtk_soc_eth 15100000.ethernet eth1: configuring for phy/sgmii link mode
Fri Dec 15 12:37:53 2023 daemon.notice netifd: Interface 'wan' is enabled
Fri Dec 15 12:37:53 2023 daemon.notice netifd: Interface 'wan' is setting up now
Fri Dec 15 12:37:53 2023 daemon.notice netifd: VLAN 'eth1.10' link is down
Fri Dec 15 12:37:53 2023 daemon.notice netifd: Interface 'wan' has link connectivity loss
Fri Dec 15 12:37:53 2023 daemon.notice netifd: Network device 'eth1' link is down
Fri Dec 15 12:37:53 2023 daemon.notice netifd: wan (2313): Command failed: ubus call network.interface notify_proto { "action": 1, "command": [ "\/usr\/sbin\/pppd", "nodetach", "ipparam", "wan", "ifname", "pppoe-wan", "lcp-echo-interval", "1", "lcp-echo-failure", "5", "lcp-echo-adaptive", "set", "PEERDNS=1", "nodefaultroute", "usepeerdns", "maxfail", "1", "user", "user@isp", "password", "safepassword", "ip-up-script", "\/lib\/netifd\/ppp-up", "ip-down-script", "\/lib\/netifd\/ppp-down", "mtu", "1492", "mru", "1492", "plugin", "pppoe.so", "nic-eth1.10" ], "interface": "wan" } (Permission denied)
Fri Dec 15 12:37:53 2023 daemon.notice netifd: Interface 'wan' is now down
Fri Dec 15 12:37:53 2023 daemon.notice netifd: Interface 'wan' is disabled
Fri Dec 15 12:37:53 2023 kern.info kernel: [65466.587577] mtk_soc_eth 15100000.ethernet eth1: PHY [mdio-bus:01] driver [RTL8221B-VB-CG 2.5Gbps PHY] (irq=62)
Fri Dec 15 12:37:53 2023 kern.info kernel: [65466.597826] mtk_soc_eth 15100000.ethernet eth1: configuring for phy/sgmii link mode
Fri Dec 15 12:37:53 2023 daemon.notice netifd: Interface 'wan' is enabled
Fri Dec 15 12:37:53 2023 user.notice firewall: Reloading firewall due to ifdown of wan ()
Fri Dec 15 12:37:54 2023 user.notice kmwan: config json str={ "op": 3, "data": { "cells": [ "wan" ] } }
when rolling back the logs are a bit all over (i.e. there are other things happening in between these steps (namely firewall and wlan setups)
Fri Dec 15 12:47:11 2023 daemon.notice netifd: Network device 'eth1' link is up
Fri Dec 15 12:47:11 2023 daemon.notice netifd: VLAN 'eth1.10' link is up
Fri Dec 15 12:47:11 2023 daemon.notice netifd: Interface 'wan' has link connectivity
Fri Dec 15 12:47:11 2023 daemon.notice netifd: Interface 'wan' is setting up now
Fri Dec 15 12:47:12 2023 daemon.info pppd[5238]: Plugin pppoe.so loaded.
Fri Dec 15 12:47:12 2023 daemon.info pppd[5238]: PPPoE plugin from pppd 2.4.9
Fri Dec 15 12:47:12 2023 daemon.notice pppd[5238]: pppd 2.4.9 started by root, uid 0
Fri Dec 15 12:47:12 2023 daemon.info pppd[5238]: PPP session is 1
Fri Dec 15 12:47:12 2023 daemon.warn pppd[5238]: Connected to [Media_converter_MAC_add] via interface eth1.10
Fri Dec 15 12:47:12 2023 kern.info kernel: [ 22.268641] pppoe-wan: renamed from ppp0
Fri Dec 15 12:47:12 2023 daemon.info pppd[5238]: Renamed interface ppp0 to pppoe-wan
Fri Dec 15 12:47:12 2023 daemon.info pppd[5238]: Using interface pppoe-wan
Fri Dec 15 12:47:12 2023 daemon.notice pppd[5238]: Connect: pppoe-wan <--> eth1.10
Fri Dec 15 12:47:15 2023 daemon.notice pppd[5238]: peer from calling number [Media_converter_MAC_add] authorized
#This IPV6 is different from the above and the connection is done in pppoe-wan.IPv6 rather than eth1.IPv6
Fri Dec 15 12:47:15 2023 daemon.info avahi-daemon[4781]: Joining mDNS multicast group on interface pppoe-wan.IPv6 with address wwww::wwww:wwww:wwww:wwww.
Fri Dec 15 12:47:15 2023 daemon.info avahi-daemon[4781]: New relevant interface pppoe-wan.IPv6 for mDNS.
Fri Dec 15 12:47:15 2023 daemon.notice pppd[5238]: local LL address wwww::wwww:wwww:wwww:wwww
Fri Dec 15 12:47:15 2023 daemon.notice pppd[5238]: remote LL address yyyy::yyyy:yyyy:yyyy:yyyy
Fri Dec 15 12:47:15 2023 daemon.info avahi-daemon[4781]: Registering new address record for fe80::34d9:6611:7cf7:2260 on pppoe-wan.*.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: Joining mDNS multicast group on interface pppoe-wan.IPv4 with address 80.200.150.76.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: New relevant interface pppoe-wan.IPv4 for mDNS.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: Registering new address record for 80.200.150.76 on pppoe-wan.IPv4.
Fri Dec 15 12:47:16 2023 daemon.notice pppd[5238]: local IP address YYY.YYY.YYY.YYY
Fri Dec 15 12:47:16 2023 daemon.notice pppd[5238]: remote IP address ZZZ.ZZZ.ZZZ.ZZZ
Fri Dec 15 12:47:16 2023 daemon.notice pppd[5238]: primary DNS address 195.238.2.21
Fri Dec 15 12:47:16 2023 daemon.notice pppd[5238]: secondary DNS address 195.238.2.22
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: Withdrawing address record for 80.200.150.76 on pppoe-wan.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: Leaving mDNS multicast group on interface pppoe-wan.IPv4 with address 80.200.150.76.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: Interface pppoe-wan.IPv4 no longer relevant for mDNS.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: Joining mDNS multicast group on interface pppoe-wan.IPv4 with address 80.200.150.76.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: New relevant interface pppoe-wan.IPv4 for mDNS.
Fri Dec 15 12:47:16 2023 daemon.info avahi-daemon[4781]: Registering new address record for 80.200.150.76 on pppoe-wan.IPv4.
Fri Dec 15 12:47:16 2023 daemon.notice netifd: Network device 'pppoe-wan' link is up
Fri Dec 15 12:47:16 2023 daemon.notice netifd: Interface 'wan' is now up
Fri Dec 15 12:47:16 2023 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Fri Dec 15 12:47:17 2023 user.notice kmwan: config json str={ "op": 2, "data": { "cells": [ { "interface": "wan", "netdev": "pppoe-wan", "track_mode": "force", "addr_type": 4, "tracks": [ { "type": "ping", "ip": "1.1.1.1" }, { "type": "ping", "ip": "8.8.8.8" }, { "type": "ping", "ip": "208.67.222.222" }, { "type": "ping", "ip": "208.67.220.220" } ] } ] } }
Fri Dec 15 12:47:17 2023 kern.debug kernel: [ 27.268511] [add_dev_config 307]add node success. iface:wan, dev:pppoe-wan, ifindex:15
Fri Dec 15 12:47:17 2023 kern.debug kernel: [ 27.276451] [__set_fib_nh 94]ifindex:15 route_flag:2
I hope this helps with troubleshooting!