My PPPOE suddenly started dropping out this afternoon, I have made no changes on my side and no reported issues in my area - I have confirmed there is nothing wrong (as such) with the PPPOE coming into the house, as its working fine on my R7800 (Running DD-WRT).
The following happens whilst trying to connect:
It will attempt to connect, occasionally giving me "Error: Connection attempt failed" error.. It will then establish a connection (give me the WAN IP, etc), but within seconds disconnect.. It will then retry and a few minutes later make another connection... and so on..
I have enabled debugging for pppd and copied the relevant pppd log below - the disconnection happened as part of that log.
Setup:
Build: [OpenWrt SNAPSHOT (r27041-7686ce4a91)](https://openwrt.org/)
Hardware: Raspberry PI 5
Connection: TP-LINK UE300 USB 3.0 to Gigabit Ethernet Universal Adapter
Provider: Vodafone UK (Cityfibre)
Error Log: (IPs removed just in case.. XXX=Local IP, YYY=Remote IP)
Fri Aug 2 22:07:25 2024 daemon.debug pppd[31917]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Fri Aug 2 22:07:25 2024 daemon.debug pppd[31917]: dst ff:ff:ff:ff:ff:ff src 00:e0:4c:09:38:a0
Fri Aug 2 22:07:25 2024 daemon.debug pppd[31917]: [service-name] [host-uniq ad 7c 00 00]
Fri Aug 2 22:07:30 2024 daemon.debug pppd[31917]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Fri Aug 2 22:07:30 2024 daemon.debug pppd[31917]: dst ff:ff:ff:ff:ff:ff src 00:e0:4c:09:38:a0
Fri Aug 2 22:07:30 2024 daemon.debug pppd[31917]: [service-name] [host-uniq ad 7c 00 00]
Fri Aug 2 22:07:35 2024 daemon.warn pppd[31917]: Timeout waiting for PADO packets
Fri Aug 2 22:07:35 2024 daemon.err pppd[31917]: Unable to complete PPPoE Discovery
Fri Aug 2 22:07:35 2024 daemon.info pppd[31917]: Exit.
Fri Aug 2 22:07:35 2024 daemon.info pppd[32025]: Plugin pppoe.so loaded.
Fri Aug 2 22:07:35 2024 daemon.info pppd[32025]: PPPoE plugin from pppd 2.4.9
Fri Aug 2 22:07:35 2024 daemon.notice pppd[32025]: pppd 2.4.9 started by root, uid 0
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: dst ff:ff:ff:ff:ff:ff src 00:e0:4c:09:38:a0
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: [service-name] [host-uniq 19 7d 00 00]
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 49
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: dst 00:e0:4c:09:38:a0 src 20:e0:9c:0f:60:0b
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: [service-name] [AC-name SQYN02-BNG-C1] [host-uniq 19 7d 00 00] [AC-cookie 55 f2 c7 ae 39 64 c9 e2 2c 2e ad 1d 1d 17 c6 0a]
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: dst 20:e0:9c:0f:60:0b src 00:e0:4c:09:38:a0
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: [service-name] [host-uniq 19 7d 00 00] [AC-cookie 55 f2 c7 ae 39 64 c9 e2 2c 2e ad 1d 1d 17 c6 0a]
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: Recv PPPOE Discovery V1T1 PADS session 0x1884 length 12
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: dst 00:e0:4c:09:38:a0 src 20:e0:9c:0f:60:0b
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: [service-name] [host-uniq 19 7d 00 00]
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: PADS: Service-Name: ''
Fri Aug 2 22:07:35 2024 daemon.info pppd[32025]: PPP session is 6276
Fri Aug 2 22:07:35 2024 daemon.warn pppd[32025]: Connected to 20:e0:9c:0f:60:0b via interface eth1.911
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: using channel 6
Fri Aug 2 22:07:35 2024 daemon.info pppd[32025]: Using interface pppoe-wan
Fri Aug 2 22:07:35 2024 daemon.notice pppd[32025]: Connect: pppoe-wan <--> eth1.911
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x4297d464>]
Fri Aug 2 22:07:35 2024 daemon.debug pppd[32025]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x4297d464>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: rcvd [LCP ConfReq id=0x7d <mru 1492> <auth chap MD5> <magic 0x11dfe924>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: sent [LCP ConfAck id=0x7d <mru 1492> <auth chap MD5> <magic 0x11dfe924>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: sent [LCP EchoReq id=0x0 magic=0x4297d464]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: rcvd [CHAP Challenge id=0x1 <c4307c2bdaac1f6ba0c4ad40535fe5cda9a3e6cb4a78c3716d484880395eba7e8e37a9e86448d3848d02c4e0e02b2f0ace16d5980e198a7b61527c9b>, name = "SQYN02-BNG-C1"]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: sent [CHAP Response id=0x1 <fffbcf7af0e87454d85b276e9a77a0fa>, name = "##USERNAME##@broadband.vodafone.co.uk"]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: rcvd [LCP EchoRep id=0x0 magic=0x11dfe924]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: rcvd [CHAP Success id=0x1 "CHAP authentication success"]
Fri Aug 2 22:07:38 2024 daemon.info pppd[32025]: CHAP authentication succeeded: CHAP authentication success
Fri Aug 2 22:07:38 2024 daemon.notice pppd[32025]: CHAP authentication succeeded
Fri Aug 2 22:07:38 2024 daemon.notice pppd[32025]: peer from calling number 20:E0:9C:0F:60:0B authorized
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: sent [IPV6CP ConfReq id=0x1 <addr fe80::b9b2:8a8c:f7df:499e>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: rcvd [IPCP ConfReq id=0x5f <addr YYY.YYY.YYY.YYY>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: sent [IPCP ConfAck id=0x5f <addr YYY.YYY.YYY.YYY>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: rcvd [IPCP ConfNak id=0x1 <addr XXX.XXX.XXX.XXX> <ms-dns1 90.255.255.90> <ms-dns2 90.255.255.255>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: sent [IPCP ConfReq id=0x2 <addr XXX.XXX.XXX.XXX> <ms-dns1 90.255.255.90> <ms-dns2 90.255.255.255>]
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: rcvd [IPCP ConfAck id=0x2 <addr XXX.XXX.XXX.XXX> <ms-dns1 90.255.255.90> <ms-dns2 90.255.255.255>]
Fri Aug 2 22:07:38 2024 daemon.notice pppd[32025]: local IP address XXX.XXX.XXX.XXX
Fri Aug 2 22:07:38 2024 daemon.notice pppd[32025]: remote IP address YYY.YYY.YYY.YYY
Fri Aug 2 22:07:38 2024 daemon.notice pppd[32025]: primary DNS address 90.255.255.90
Fri Aug 2 22:07:38 2024 daemon.notice pppd[32025]: secondary DNS address 90.255.255.255
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: Script /lib/netifd/ppp-up started (pid 32376)
Fri Aug 2 22:07:38 2024 daemon.debug pppd[32025]: Script /lib/netifd/ppp-up finished (pid 32376), status = 0x1
Fri Aug 2 22:07:41 2024 daemon.debug pppd[32025]: sent [IPV6CP ConfReq id=0x1 <addr fe80::b9b2:8a8c:f7df:499e>]
Fri Aug 2 22:07:44 2024 daemon.debug pppd[32025]: sent [IPV6CP ConfReq id=0x1 <addr fe80::b9b2:8a8c:f7df:499e>]
Fri Aug 2 22:07:47 2024 daemon.debug pppd[32025]: sent [IPV6CP ConfReq id=0x1 <addr fe80::b9b2:8a8c:f7df:499e>]
Fri Aug 2 22:07:50 2024 daemon.debug pppd[32025]: sent [IPV6CP ConfReq id=0x1 <addr fe80::b9b2:8a8c:f7df:499e>]
Fri Aug 2 22:07:50 2024 daemon.info pppd[32025]: Terminating on signal 15
Fri Aug 2 22:07:50 2024 daemon.info pppd[32025]: Connect time 0.2 minutes.
Fri Aug 2 22:07:50 2024 daemon.info pppd[32025]: Sent 236 bytes, received 3349 bytes.
Fri Aug 2 22:07:50 2024 daemon.debug pppd[32025]: Script /lib/netifd/ppp-down started (pid 713)
Fri Aug 2 22:07:50 2024 daemon.debug pppd[32025]: sent [LCP TermReq id=0x2 "User request"]
Fri Aug 2 22:07:50 2024 daemon.debug pppd[32025]: Script /lib/netifd/ppp-down finished (pid 713), status = 0x1
Fri Aug 2 22:07:50 2024 daemon.debug pppd[32025]: rcvd [LCP TermAck id=0x2]
Fri Aug 2 22:07:50 2024 daemon.notice pppd[32025]: Connection terminated.
Fri Aug 2 22:07:50 2024 daemon.info pppd[32025]: Exit.
Fri Aug 2 22:07:54 2024 daemon.info pppd[2301]: Plugin pppoe.so loaded.
Fri Aug 2 22:07:54 2024 daemon.info pppd[2301]: PPPoE plugin from pppd 2.4.9
Fri Aug 2 22:07:55 2024 daemon.notice pppd[2301]: pppd 2.4.9 started by root, uid 0
Fri Aug 2 22:07:55 2024 daemon.debug pppd[2301]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Fri Aug 2 22:07:55 2024 daemon.debug pppd[2301]: dst ff:ff:ff:ff:ff:ff src 00:e0:4c:09:38:a0
Fri Aug 2 22:07:55 2024 daemon.debug pppd[2301]: [service-name] [host-uniq fd 08 00 00]
Fri Aug 2 22:08:00 2024 daemon.debug pppd[2301]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Fri Aug 2 22:08:00 2024 daemon.debug pppd[2301]: dst ff:ff:ff:ff:ff:ff src 00:e0:4c:09:38:a0
Fri Aug 2 22:08:00 2024 daemon.debug pppd[2301]: [service-name] [host-uniq fd 08 00 00]
Fri Aug 2 22:08:05 2024 daemon.debug pppd[2301]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Fri Aug 2 22:08:05 2024 daemon.debug pppd[2301]: dst ff:ff:ff:ff:ff:ff src 00:e0:4c:09:38:a0
Fri Aug 2 22:08:05 2024 daemon.debug pppd[2301]: [service-name] [host-uniq fd 08 00 00]
Fri Aug 2 22:08:10 2024 daemon.warn pppd[2301]: Timeout waiting for PADO packets
Fri Aug 2 22:08:10 2024 daemon.err pppd[2301]: Unable to complete PPPoE Discovery
Fri Aug 2 22:08:10 2024 daemon.info pppd[2301]: Exit.
Fri Aug 2 22:08:10 2024 daemon.info pppd[2377]: Plugin pppoe.so loaded.
Fri Aug 2 22:08:10 2024 daemon.info pppd[2377]: PPPoE plugin from pppd 2.4.9
Fri Aug 2 22:08:10 2024 daemon.notice pppd[2377]: pppd 2.4.9 started by root, uid 0
Fri Aug 2 22:08:10 2024 daemon.debug pppd[2377]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Fri Aug 2 22:08:10 2024 daemon.debug pppd[2377]: dst ff:ff:ff:ff:ff:ff src 00:e0:4c:09:38:a0
Fri Aug 2 22:08:10 2024 daemon.debug pppd[2377]: [service-name] [host-uniq 49 09 00 00]
Please connect to your OpenWrt device using ssh and copy the output of the following commands and post it here using the "Preformatted text </> " button:
Remember to redact passwords, MAC addresses and any public IP addresses you may have:
ubus call system board
cat /etc/config/network
cat /etc/config/dhcp
cat /etc/config/firewall
Please find output below.. For completeness, I am currently running (as temp workaround) the WAN off 192.168.0.2, in case you wonder why gateway is set to that IP, etc). Also build in this post is different than the first post, as I wanted to test an older build I had.
Could you try disabling IPv6 on the wan link (just for testing) since it seems to fail there, but that might simply be a timing issue? Mind you, this is not intended as solution, just to see whether it is the IPv6 negotiations that cause the termination.
I used Luci.. Is there are any default parameters in there (such as keepalive), it would have been added by me using nano, to try suggestions I've found.
The config I have been running successfully for the last 2 weeks is:
I have restored my OpenWrt back to the last known good backup (2 weeks ago) just to be on the safe side, to rule out any changes to anything, but no luck.
Although I tried with keepalive set to "5 5" earlier, I have now set it to "10 10", and it has stayed connected for 1h 30min (and still connected).. Does this change make sense with the above log entries in mind? Would this potentially be the fix for my problems?
It seems IPv6 negotiations were the canary not the root cause... something on the other side just seems to be a tad slow, so upping the keep alive interval seems fine... assuming that this reliably fixes the issue.