PPP daemon keeps losing IP when IPv6 is enabled

Borromini · September 9, 2020, 9:21am

My brother's PPP connection started failing yesterday. Logread showed the ppp daemon obtaining an IP, then having to release it because of configuration issues, over and over. The debug log points to an IPv6 issue with PPP, and disabling IPv6 did indeed work around it. However, since IPv6 seemingly used to work just fine before, I'd like to fix this (since the ISP will, at some point, be migrating to IPv6 only). It's a Belgian ISP (Proximus), in case people have seen something similar. The router is behind the bridged ISP supplied modem. The router runs a recent 19.07 build (post 19.07.3, pre 19.07.4). PPP version is 2.4.7.git-2019-05-25-3.

Googling this particular error message daemon.debug pppd[19221]: sent [IPV6CP TermReq id=0x2 "Interface configuration failed"]does not bring up any solutions, only people reporting similar issues unfortunately.

Network configuration snippet:

config interface 'wan'
	option _orig_ifname 'eth0'
	option _orig_bridge 'true'
	option ifname 'eth0'
	option proto 'pppoe'
	option password '$password'
	option ipv6 '0'
	option username '$login'

The ipv6 option used to be 'auto' but has been set to 0 to work around the disconnect for now.

Log:

logread -e pppd -f
Tue Sep  8 18:57:36 2020 daemon.info pppd[19221]: Plugin rp-pppoe.so loaded.
Tue Sep  8 18:57:36 2020 daemon.info pppd[19221]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Tue Sep  8 18:57:36 2020 daemon.notice pppd[19221]: pppd 2.4.7 started by root, uid 0
Tue Sep  8 18:57:36 2020 daemon.debug pppd[19221]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Tue Sep  8 18:57:36 2020 daemon.debug pppd[19221]:  dst ff:ff:ff:ff:ff:ff  src 00:0d:b9:xx:xx:xx
Tue Sep  8 18:57:36 2020 daemon.debug pppd[19221]:  [service-name] [host-uniq  15 4b 00 00]
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  dst ff:ff:ff:ff:ff:ff  src 00:0d:b9:xx:xx:xx
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  [service-name] [host-uniq  15 4b 00 00]
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  dst 00:0d:b9:xx:xx:xx  src 24:21:xx:xx:xx:xx
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  [service-name] [AC-name ttnle52lon01] [host-uniq  15 4b 00 00] [AC-cookie  0a 47 32 c6 af a0 98 80 be c4 21 97 69 5a c1 a8]
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  dst 24:21:xx:xx:xx:xx  src 00:0d:b9:xx:xx:xx
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  [service-name] [host-uniq  15 4b 00 00] [AC-cookie  0a 47 32 c6 af a0 98 80 be c4 21 97 69 5a c1 a8]
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: Recv PPPOE Discovery V1T1 PADS session 0x1 length 12
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  dst 00:0d:b9:xx:xx:xx  src 24:21:xx:xx:xx:xx
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]:  [service-name] [host-uniq  15 4b 00 00]
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: PADS: Service-Name: ''
Tue Sep  8 18:57:41 2020 daemon.info pppd[19221]: PPP session is 1
Tue Sep  8 18:57:41 2020 daemon.warn pppd[19221]: Connected to 24:21:xx:xx:xx:xx via interface eth0
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: using channel 83
Tue Sep  8 18:57:41 2020 daemon.info pppd[19221]: Renamed interface ppp0 to pppoe-wan
Tue Sep  8 18:57:41 2020 daemon.info pppd[19221]: Using interface pppoe-wan
Tue Sep  8 18:57:41 2020 daemon.notice pppd[19221]: Connect: pppoe-wan <--> eth0
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0xc4737bb0>]
Tue Sep  8 18:57:41 2020 daemon.debug pppd[19221]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0xc4737bb0>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0xc4737bb0>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0xc4737bb0>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [LCP ConfReq id=0x34 <mru 1492> <auth chap MD5> <magic 0x1171d6d>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [LCP ConfAck id=0x34 <mru 1492> <auth chap MD5> <magic 0x1171d6d>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [LCP EchoReq id=0x0 magic=0xc4737bb0]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [CHAP Challenge id=0x1 <21d6dd7297643f11dcd4d39572901105fdda3e1a172b01c9dd3c3b2a011d96227474940c58531db428f14a1b025b200037dd9acd091b9767585211d86fa77a>, name = "ttnle52lon01"]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [CHAP Response id=0x1 <1f8962cac359ce763993338bf31ac0a4>, name = "$login"]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [LCP EchoRep id=0x0 magic=0x1171d6d]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [CHAP Success id=0x1 "QOS"]
Tue Sep  8 18:57:44 2020 daemon.info pppd[19221]: CHAP authentication succeeded: QOS
Tue Sep  8 18:57:44 2020 daemon.notice pppd[19221]: CHAP authentication succeeded
Tue Sep  8 18:57:44 2020 daemon.notice pppd[19221]: peer from calling number 24:21:xx:xx:xx:xx authorized
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [IPV6CP ConfReq id=0x1 <addr fe80::1536:6f51:2376:6aa2>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [IPV6CP ConfReq id=0x1c <addr fe80::2621:24ff:fe91:b63f>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [IPV6CP ConfAck id=0x1c <addr fe80::2621:24ff:fe91:b63f>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [IPCP ConfReq id=0xd2 <addr 10.24.193.42>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [IPCP ConfAck id=0xd2 <addr 10.24.193.42>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [IPV6CP ConfAck id=0x1 <addr fe80::1536:6f51:2376:6aa2>]
Tue Sep  8 18:57:44 2020 daemon.err pppd[19221]: sif6addr: ioctl(SIOCSIFADDR): Permission denied (line 2642)
Tue Sep  8 18:57:44 2020 daemon.warn pppd[19221]: sif6addr failed
Tue Sep  8 18:57:44 2020 daemon.warn pppd[19221]: cif6addr: ioctl(SIOCDIFADDR): No such address
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [IPV6CP TermReq id=0x2 "Interface configuration failed"]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [IPCP ConfNak id=0x1 <addr 81.245.219.175> <ms-dns1 195.238.2.21> <ms-dns2 195.238.2.22>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [IPCP ConfReq id=0x2 <addr 81.245.219.175> <ms-dns1 195.238.2.21> <ms-dns2 195.238.2.22>]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [LCP TermReq id=0x35]
Tue Sep  8 18:57:44 2020 daemon.info pppd[19221]: LCP terminated by peer
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: sent [LCP TermAck id=0x35]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: rcvd [IPV6CP TermAck id=0x2]
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: Discarded non-LCP packet when LCP not open
Tue Sep  8 18:57:44 2020 daemon.notice pppd[19221]: Modem hangup
Tue Sep  8 18:57:44 2020 daemon.notice pppd[19221]: Connection terminated.
Tue Sep  8 18:57:44 2020 daemon.info pppd[19221]: Connect time 0.2 minutes.
Tue Sep  8 18:57:44 2020 daemon.info pppd[19221]: Sent 60 bytes, received 60 bytes.
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]: Send PPPOE Discovery V1T1 PADT session 0x1 length 28
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]:  dst 24:21:xx:xx:xx:xx  src 00:0d:b9:xx:xx:xx
Tue Sep  8 18:57:44 2020 daemon.debug pppd[19221]:  [host-uniq  15 4b 00 00] [AC-cookie  0a 47 32 c6 af a0 98 80 be c4 21 97 69 5a c1 a8]
Tue Sep  8 18:57:44 2020 daemon.info pppd[19221]: Sent PADT
Tue Sep  8 18:57:44 2020 daemon.info pppd[19221]: Exit.

svanheule · September 9, 2020, 9:41am

I also have Proximus as my ISP, but don't have any issues right now. I currently use Debian to set up the PPPoE session, but this is my old config on OpenWrt:

config interface 'wan'
        option ifname 'eth1'
        option proto 'pppoe'
        option username 'USERNAME'
        option password 'PASSWORD'
        option ipv6 'auto'

This is my current config for pppd (ens4 is the WAN interface), ppp is version 2.4.7-2+4.1+deb10u1:

user USERNAME
pty "/usr/sbin/pppoe -I ens4 -T 80 -m 1452"
noipdefault
defaultroute
hide-password
lcp-echo-interval 20
lcp-echo-failure 3
connect /bin/true
noauth
persist
mtu 1492
noaccomp
default-asyncmap
+ipv6
ipv6cp-accept-local
ipparam ipv6pd

To get a public IPv6 address, I also use dhcp6c (ens3 and ens3.10 are LAN interfaces):

interface ppp0 {
	send ia-pd 1;
	send rapid-commit;
	request ntp-servers;
};

id-assoc pd 1 {
	prefix-interface ens3 {
		sla-id 1;
		sla-len 8;
	};
	prefix-interface ens3.10 {
		sla-id 10;
		sla-len 8;
	};
};

slh · September 9, 2020, 7:32pm

What device are you using for this?

Background: I'm seeing my tl-wdr3600/ar9344 and tl-wdr4300/ar9344 freezing up on heavy traffic (speedtest or large downloads) while connecting via PPPoE (plain ethernet is fine). The very same conditions work fine on lantiq VRX268 or ipq4019 though.

Borromini · September 9, 2020, 7:44pm

This is an APU2. OpenWrt version is 19.07-SNAPSHOT, r11144+14-2ca5a386ee (with a few things not related to PPP cherry-picked on top).

migube · November 8, 2020, 8:54am

hi guys

stumbled upon your post, I'm on Proximus too, and using a rapsberry pi 4 + opwenwrt (wulfy23 builds).
As soon as I start a big file upload, I get the modem hangup after mins/hours.
Sometimes the pppoe sessions gets back, sometimes it fails. At least on ipv6 (though it then reconnects on ipv4, the ipV6 is down, and no internet working).

So tx for your tip of disabling ipv6, let me test this

my logs when failing:

Sun Nov  8 09:40:02 2020 daemon.notice pppd[18440]: Modem hangup
Sun Nov  8 09:40:02 2020 daemon.info pppd[18440]: Connect time 19.2 minutes.
Sun Nov  8 09:40:02 2020 daemon.info pppd[18440]: Sent 334661324 bytes, received 83278300 bytes.
Sun Nov  8 09:40:02 2020 daemon.debug pppd[18440]: Script /lib/netifd/ppp-down started (pid 21129)
Sun Nov  8 09:40:02 2020 daemon.debug dnsmasq[14629]: stopped listening on pppoe-pppoe(#12): 81.240.202.195 port 53
Sun Nov  8 09:40:02 2020 daemon.debug dnsmasq[14629]: stopped listening on pppoe-pppoe(#12): fe80::745a:5d1b:964c:117b%pppoe-pppoe port 53
Sun Nov  8 09:40:02 2020 daemon.err odhcp6c[18548]: Failed to send RS (Permission denied)
Sun Nov  8 09:40:02 2020 daemon.notice netifd: Network device 'pppoe-pppoe' link is down
Sun Nov  8 09:40:02 2020 daemon.notice netifd: Network alias 'pppoe-pppoe' link is down
Sun Nov  8 09:40:02 2020 daemon.notice netifd: Interface 'pppoe_6' has link connectivity loss
Sun Nov  8 09:40:02 2020 daemon.err odhcp6c[18548]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)
Sun Nov  8 09:40:02 2020 daemon.debug pppd[18440]: Script /lib/netifd/ppp-down started (pid 21135)
Sun Nov  8 09:40:02 2020 daemon.notice pppd[18440]: Connection terminated.
Sun Nov  8 09:40:02 2020 daemon.info pppd[18440]: Connect time 19.2 minutes.
Sun Nov  8 09:40:02 2020 daemon.info pppd[18440]: Sent 334661324 bytes, received 83278300 bytes.
Sun Nov  8 09:40:02 2020 daemon.debug dnsmasq[14629]: stopped listening on pppoe-pppoe(#12): 2a02:a03f:cfef:4dc1:745a:5d1b:964c:117b port 53
Sun Nov  8 09:40:02 2020 daemon.notice netifd: pppoe_6 (18548): Command failed: Permission denied
Sun Nov  8 09:40:02 2020 daemon.notice netifd: Interface 'pppoe' has lost the connection
Sun Nov  8 09:40:02 2020 daemon.warn dnsmasq[14629]: no servers found in /tmp/resolv.conf.d/resolv.conf.auto, will retry
Sun Nov  8 09:40:02 2020 user.notice ModemManager: hotplug: remove network interface pppoe-pppoe: event processed
Sun Nov  8 09:40:02 2020 user.notice ModemManager: hotplug: event reported: action=remove, name=pppoe-pppoe, subsystem=net
Sun Nov  8 09:40:03 2020 user.notice mwan3-hotplug[21149]: mwan3 hotplug ifdown on pppoe not called because globally disabled
Sun Nov  8 09:40:03 2020 daemon.debug pppd[18440]: Send PPPOE Discovery V1T1 PADT session 0x1 length 28
Sun Nov  8 09:40:03 2020 daemon.debug pppd[18440]:  dst 24:21:24:af:ab:85  src 00:0e:c6:6b:d0:97
Sun Nov  8 09:40:03 2020 daemon.debug pppd[18440]:  [host-uniq  08 48 00 00] [AC-cookie  cd f9 8c e7 b9 35 19 59 5c 67 b7 93 e6 a2 2f 49]
Sun Nov  8 09:40:03 2020 daemon.info pppd[18440]: Sent PADT
Sun Nov  8 09:40:03 2020 daemon.debug pppd[18440]: Script /lib/netifd/ppp-down finished (pid 21129), status = 0x1
Sun Nov  8 09:40:03 2020 daemon.debug pppd[18440]: Script /lib/netifd/ppp-down finished (pid 21135), status = 0x1
Sun Nov  8 09:40:03 2020 daemon.info pppd[18440]: Exit.
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Interface 'pppoe' is now down
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Interface 'pppoe' is setting up now
Sun Nov  8 09:40:03 2020 daemon.err insmod: module is already loaded - slhc
Sun Nov  8 09:40:03 2020 daemon.err insmod: module is already loaded - ppp_generic
Sun Nov  8 09:40:03 2020 daemon.err insmod: module is already loaded - pppox
Sun Nov  8 09:40:03 2020 daemon.err insmod: module is already loaded - pppoe
Sun Nov  8 09:40:03 2020 daemon.info pppd[21279]: Plugin rp-pppoe.so loaded.
Sun Nov  8 09:40:03 2020 daemon.info pppd[21279]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.8
Sun Nov  8 09:40:03 2020 daemon.notice pppd[21279]: pppd 2.4.8 started by root, uid 0
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  dst ff:ff:ff:ff:ff:ff  src 00:0e:c6:6b:d0:97
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  [service-name] [host-uniq  1f 53 00 00]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  dst 00:0e:c6:6b:d0:97  src 24:21:24:af:ab:85
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  [service-name] [AC-name ttnle69arc01] [host-uniq  1f 53 00 00] [AC-cookie  cd f9 8c e7 b9 35 19 59 5c 67 b7 93 e6 a2 2f 49]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  dst 24:21:24:af:ab:85  src 00:0e:c6:6b:d0:97
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  [service-name] [host-uniq  1f 53 00 00] [AC-cookie  cd f9 8c e7 b9 35 19 59 5c 67 b7 93 e6 a2 2f 49]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: Recv PPPOE Discovery V1T1 PADS session 0x1 length 12
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  dst 00:0e:c6:6b:d0:97  src 24:21:24:af:ab:85
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]:  [service-name] [host-uniq  1f 53 00 00]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: PADS: Service-Name: ''
Sun Nov  8 09:40:03 2020 daemon.info pppd[21279]: PPP session is 1
Sun Nov  8 09:40:03 2020 daemon.warn pppd[21279]: Connected to 24:21:24:af:ab:85 via interface eth1
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: using channel 3
Sun Nov  8 09:40:03 2020 kern.info kernel: [ 1741.975956] pppoe-pppoe: renamed from ppp0
Sun Nov  8 09:40:03 2020 daemon.info pppd[21279]: Renamed interface ppp0 to pppoe-pppoe
Sun Nov  8 09:40:03 2020 daemon.info pppd[21279]: Using interface pppoe-pppoe
Sun Nov  8 09:40:03 2020 daemon.notice pppd[21279]: Connect: pppoe-pppoe <--> eth1
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x6a77f23e>]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: rcvd [LCP ConfReq id=0xba <mru 1492> <auth chap MD5> <magic 0x351444d2>]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: sent [LCP ConfAck id=0xba <mru 1492> <auth chap MD5> <magic 0x351444d2>]
Sun Nov  8 09:40:03 2020 user.notice ModemManager: hotplug: add network interface ppp0: event processed
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x6a77f23e>]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: sent [LCP EchoReq id=0x0 magic=0x6a77f23e]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: rcvd [CHAP Challenge id=0x1 <43fb2de9b5e9bff4f4ada0f3ef5e71185dcf760c6848a68b1e9699f856ee77196aa483200e431682f0>, name = "ttnle69arc01"]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: sent [CHAP Response id=0x1 <0f5f49c03fde15942156b08f6b3978d6>, name = "xxx@PROXIMUS"]
Sun Nov  8 09:40:03 2020 user.notice ModemManager: hotplug: event reported: action=add, name=ppp0, subsystem=net
Sun Nov  8 09:40:03 2020 user.notice ModemManager: hotplug: error: parent device sysfspath not found
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: rcvd [LCP EchoRep id=0x0 magic=0x351444d2]
Sun Nov  8 09:40:03 2020 user.notice ModemManager: hotplug: move network interface pppoe-pppoe: event processed
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: rcvd [CHAP Success id=0x1 "CHAP authentication success"]
Sun Nov  8 09:40:03 2020 daemon.info pppd[21279]: CHAP authentication succeeded: CHAP authentication success
Sun Nov  8 09:40:03 2020 daemon.notice pppd[21279]: CHAP authentication succeeded
Sun Nov  8 09:40:03 2020 daemon.notice pppd[21279]: peer from calling number 24:21:24:AF:AB:85 authorized
Sun Nov  8 09:40:03 2020 user.notice ModemManager: hotplug: event reported: action=move, name=pppoe-pppoe, subsystem=net
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: sent [IPV6CP ConfReq id=0x1 <addr fe80::8d44:c172:61a2:2034>]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: rcvd [IPV6CP ConfReq id=0x19 <addr fe80::2621:24ff:feaf:aa3f>]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: sent [IPV6CP ConfAck id=0x19 <addr fe80::2621:24ff:feaf:aa3f>]
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: rcvd [IPV6CP ConfAck id=0x1 <addr fe80::8d44:c172:61a2:2034>]
Sun Nov  8 09:40:03 2020 daemon.notice pppd[21279]: local  LL address fe80::8d44:c172:61a2:2034
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Network device 'pppoe-pppoe' link is up
Sun Nov  8 09:40:03 2020 daemon.notice pppd[21279]: remote LL address fe80::2621:24ff:feaf:aa3f
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Network alias 'pppoe-pppoe' link is up
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Interface 'pppoe_6' has link connectivity
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: Script /lib/netifd/ppp6-up started (pid 21336)
Sun Nov  8 09:40:03 2020 daemon.debug dnsmasq[14629]: listening on pppoe-pppoe(#13): fe80::8d44:c172:61a2:2034%pppoe-pppoe port 53
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Interface 'pppoe' is now up
Sun Nov  8 09:40:03 2020 daemon.debug pppd[21279]: Script /lib/netifd/ppp6-up finished (pid 21336), status = 0x0
Sun Nov  8 09:40:03 2020 daemon.err odhcp6c[18548]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Interface 'pppoe_6' is now down
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Interface 'pppoe_6' is disabled
Sun Nov  8 09:40:03 2020 daemon.notice netifd: Interface 'pppoe_6' has link connectivity loss
Sun Nov  8 09:40:03 2020 user.notice mwan3-hotplug[21340]: mwan3 hotplug ifup on pppoe not called because globally disabled
Sun Nov  8 09:40:03 2020 user.notice firewall: Reloading firewall due to ifup of pppoe (pppoe-pppoe)
Sun Nov  8 09:40:03 2020 user.notice nlbwmon: Reloading nlbwmon due to ifup of pppoe (pppoe-pppoe)
Sun Nov  8 09:40:03 2020 daemon.info dnsmasq[14629]: read /etc/hosts - 4 addresses
Sun Nov  8 09:40:03 2020 daemon.info dnsmasq[14629]: read /tmp/hosts/odhcpd - 0 addresses
Sun Nov  8 09:40:03 2020 daemon.info dnsmasq[14629]: read /tmp/hosts/dhcp.cfg01411c - 0 addresses
Sun Nov  8 09:40:04 2020 daemon.debug pppd[21279]: rcvd [IPCP ConfReq id=0x29 <addr 10.24.145.62>]
Sun Nov  8 09:40:04 2020 daemon.debug pppd[21279]: sent [IPCP ConfAck id=0x29 <addr 10.24.145.62>]
Sun Nov  8 09:40:04 2020 daemon.debug pppd[21279]: rcvd [IPCP ConfNak id=0x1 <addr 81.240.202.195> <ms-dns1 195.238.2.21> <ms-dns2 195.238.2.22>]
Sun Nov  8 09:40:04 2020 daemon.debug pppd[21279]: sent [IPCP ConfReq id=0x2 <addr 81.240.202.195> <ms-dns1 195.238.2.21> <ms-dns2 195.238.2.22>]
Sun Nov  8 09:40:04 2020 daemon.debug pppd[21279]: rcvd [IPCP ConfAck id=0x2 <addr 81.240.202.195> <ms-dns1 195.238.2.21> <ms-dns2 195.238.2.22>]
Sun Nov  8 09:40:04 2020 daemon.notice pppd[21279]: local  IP address 81.240.202.195
Sun Nov  8 09:40:04 2020 daemon.notice pppd[21279]: remote IP address 10.24.145.62
Sun Nov  8 09:40:04 2020 daemon.notice pppd[21279]: primary   DNS address 195.238.2.21
Sun Nov  8 09:40:04 2020 daemon.notice pppd[21279]: secondary DNS address 195.238.2.22
Sun Nov  8 09:40:04 2020 daemon.debug pppd[21279]: Script /lib/netifd/ppp-up started (pid 21847)
Sun Nov  8 09:40:04 2020 daemon.debug dnsmasq[14629]: listening on pppoe-pppoe(#13): 81.240.202.195 port 53
Sun Nov  8 09:40:04 2020 daemon.debug pppd[21279]: Script /lib/netifd/ppp-up finished (pid 21847), status = 0x1
Sun Nov  8 09:40:04 2020 user.notice firewall: Reloading firewall due to ifupdate of pppoe (pppoe-pppoe)

Borromini · November 8, 2020, 9:00am

'Glad' not to be the only one seeing this. I haven't found a solution for it yet though. I tried Userbase as well but other than taking out the OpenWrt router (which I haven't been able to test) they offered no suggestions.

Brussels region as well by any chance?

migube · November 8, 2020, 6:07pm

Hainaut, but don't think it's region specific note that I never had issues using the Bbox3 directly. there the pppoe is stable.
one disconnection atm on ipv4., which is much better than when ipv6 was on, but still too much, will keep further an eye on it
we can open a bug report , but not sure what info we'll have to provide

anon50098793 · December 30, 2020, 5:37am

possibly not related but trendy just narrowed down an issue with banip/ipv6...

Borromini · December 30, 2020, 7:05am

Thanks Wulfy, I saw your thread and thought exactly the same thing. Have it bookmarked to test!

trendy · December 30, 2020, 11:17pm

Did you try to capture with tcpdump the RAs and DHCP6 packets?

Borromini · December 31, 2020, 9:20am

No, and it's at my brother's, and because of the lockdown here I won't be going over there anytime soon. Tcpdump is not my forte. Any tips on how I should invoke tcpdump for this?

anon50098793 · December 31, 2020, 10:04am

this should do the job...

tcpdump -evn -i $(uci get network.wan6.ifname) udp port 546 or udp port 547 or '(icmp6 && (ip6[40] >= 133 && ip6[40] <= 137))'

not sure about the interface or if capturing additional ppp stuff might be useful...

Borromini · December 31, 2020, 10:15am

Thanks. Will keep it in mind and report back once I got the chance.

anon50098793 · February 3, 2021, 10:14am

another possibility: https://openwrt.org/advisory/2021-02-02-1

Borromini · March 6, 2021, 11:21am

Setting the MTU to 1492 doesn't help unfortunately:

Sat Mar  6 12:17:14 2021 kern.info kernel: [2276151.082015] igb 0000:01:00.0: changing MTU from 1492 to 1500
Sat Mar  6 12:17:14 2021 daemon.notice netifd: Interface 'wan' is disabled
Sat Mar  6 12:17:14 2021 kern.info kernel: [2276151.107235] igb 0000:01:00.0: changing MTU from 1500 to 1492
Sat Mar  6 12:17:14 2021 daemon.notice netifd: Interface 'wan' is enabled
Sat Mar  6 12:17:14 2021 kern.info kernel: [2276151.158385] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Sat Mar  6 12:17:14 2021 kern.info kernel: [2276151.164706] 8021q: adding VLAN 0 to HW filter on device eth0
Sat Mar  6 12:17:17 2021 daemon.notice netifd: Network device 'eth0' link is up
Sat Mar  6 12:17:17 2021 daemon.notice netifd: Interface 'wan' has link connectivity
Sat Mar  6 12:17:17 2021 daemon.notice netifd: Interface 'wan' is setting up now
Sat Mar  6 12:17:17 2021 kern.info kernel: [2276154.573895] igb 0000:01:00.0 eth0: igb: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Sat Mar  6 12:17:17 2021 kern.info kernel: [2276154.583764] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Sat Mar  6 12:17:17 2021 daemon.err insmod: module is already loaded - slhc
Sat Mar  6 12:17:17 2021 daemon.err insmod: module is already loaded - ppp_generic
Sat Mar  6 12:17:17 2021 daemon.err insmod: module is already loaded - pppox
Sat Mar  6 12:17:17 2021 daemon.err insmod: module is already loaded - pppoe
Sat Mar  6 12:17:17 2021 daemon.info pppd[28086]: Plugin rp-pppoe.so loaded.
Sat Mar  6 12:17:17 2021 daemon.info pppd[28086]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sat Mar  6 12:17:17 2021 daemon.notice pppd[28086]: pppd 2.4.7 started by root, uid 0
Sat Mar  6 12:17:17 2021 daemon.err pppd[28086]: Interface eth0 has MTU of 1492 -- should be at least 1500.
Sat Mar  6 12:17:17 2021 daemon.err pppd[28086]: This may cause serious connection problems.
Sat Mar  6 12:17:22 2021 daemon.info pppd[28086]: PPP session is 1
Sat Mar  6 12:17:22 2021 daemon.warn pppd[28086]: Connected to 24:21:xx:xx:xx:xx via interface eth0
Sat Mar  6 12:17:22 2021 kern.info kernel: [2276159.814310] pppoe-wan: renamed from ppp0
Sat Mar  6 12:17:22 2021 daemon.info pppd[28086]: Renamed interface ppp0 to pppoe-wan
Sat Mar  6 12:17:22 2021 daemon.info pppd[28086]: Using interface pppoe-wan
Sat Mar  6 12:17:22 2021 daemon.notice pppd[28086]: Connect: pppoe-wan <--> eth0
Sat Mar  6 12:17:22 2021 daemon.info pppd[28086]: CHAP authentication succeeded: QOS
Sat Mar  6 12:17:22 2021 daemon.notice pppd[28086]: CHAP authentication succeeded
Sat Mar  6 12:17:22 2021 daemon.notice pppd[28086]: peer from calling number 24:21:xx:xx:xx:xx authorized
Sat Mar  6 12:17:23 2021 daemon.err pppd[28086]: sif6addr: ioctl(SIOCSIFADDR): Permission denied (line 2642)
Sat Mar  6 12:17:23 2021 daemon.warn pppd[28086]: cif6addr: ioctl(SIOCDIFADDR): No such address
Sat Mar  6 12:17:23 2021 daemon.notice pppd[28086]: local  IP address xx:xx:xx:xx
Sat Mar  6 12:17:23 2021 daemon.notice pppd[28086]: remote IP address xx:xx:xx:xx
Sat Mar  6 12:17:23 2021 daemon.notice pppd[28086]: primary   DNS address xx:xx:xx:xx
Sat Mar  6 12:17:23 2021 daemon.notice pppd[28086]: secondary DNS address xx:xx:xx:xx
Sat Mar  6 12:17:23 2021 daemon.info pppd[28086]: LCP terminated by peer
Sat Mar  6 12:17:23 2021 daemon.info pppd[28086]: Connect time 0.0 minutes.
Sat Mar  6 12:17:23 2021 daemon.info pppd[28086]: Sent 0 bytes, received 4 bytes.
Sat Mar  6 12:17:23 2021 daemon.notice netifd: Interface 'wan6' is enabled
Sat Mar  6 12:17:23 2021 daemon.notice netifd: Interface 'wan' is now up
Sat Mar  6 12:17:23 2021 daemon.notice pppd[28086]: Modem hangup
Sat Mar  6 12:17:23 2021 daemon.notice pppd[28086]: Connection terminated.
Sat Mar  6 12:17:23 2021 daemon.notice netifd: Interface 'wan6' is disabled
Sat Mar  6 12:17:23 2021 daemon.notice netifd: Interface 'wan' has lost the connection
Sat Mar  6 12:17:23 2021 daemon.info pppd[28086]: Sent PADT
Sat Mar  6 12:17:23 2021 daemon.info pppd[28086]: Exit.
Sat Mar  6 12:17:23 2021 daemon.notice netifd: Interface 'wan' is now down

I'll dig further.

Borromini · March 6, 2021, 5:38pm

What makes you think that's the issue, since IPv4 works fine?