[21.02 snapshot] IPv4 PPPoE session keeps terminating?

Borromini · March 6, 2021, 10:29pm

My brother's DSL connection started acting up a while ago on 19.07 and it turned out to be an issue with IPv6 - the workaround so far being to disable IPv6.

Since the other thread is about 19.07, where IPv4 still works at least, and this one is about a 21.02 build where not even IPv4 keeps its connection, I'm keeping this separate.

From what I can tell nothing has changed concerning PPP configuration between 19.07 and 21.02 , so I kept the config (see below). Praying for the power of the version bump, I was hoping newer software might automagically fix my woes. Imagine my consternation when I realised that, on 21.02, the IPv4 PPPoE link gets cycled just like it did before on 19.07 when IPv6 was enabled.

/etc/config/network

config interface 'wan'
	option _orig_ifname 'eth0'
	option _orig_bridge 'true'
	option ifname 'eth0'
	option proto 'pppoe'
	option password '<redacted>'
	option ipv6 '0'
	option username '<redacted>'

config interface 'wan6'
	option proto 'dhcpv6'
	option reqaddress 'try'
	option reqprefix 'auto'
	option ifname '@wan'
	option auto '0'

/etc/ppp/options looks default:

#debug
logfile /dev/null
noipdefault
noaccomp
nopcomp
nocrtscts
lock
maxfail 0

I am noticing a few things:

There still seems to be IPv6 traffic somehow - I don't know why since I have it disabled (see below). It even see a few IPV6CP ConfAck lines, but those seem to be just link-local addresses?
There is a ConfNak like this:
Sat Mar 6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPCP ConfNak id=0x1 <addr xx.xx.xx.xx> <ms-dns1 xx.xx.xx.xx> <ms-dns2 xx.xx.xx.xx>]
Then a few lines down I'm seeing this, so that does look OK?
Sat Mar 6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPCP ConfAck id=0x2 <addr xx.xx.xx.xx> <ms-dns1 xx.xx.xx.xx> <ms-dns2 xx.xx.xx.xx>]

The same second the connection seems to be up the /lib/netifd/ppp-down script is started?

Full log on 21.02 (PPP debugging enabled):

Sat Mar  6 16:57:38 2021 kern.info kernel: [   77.268340] igb 0000:01:00.0 eth0: igb: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Sat Mar  6 16:57:38 2021 daemon.notice netifd: Network device 'eth0' link is up
Sat Mar  6 16:57:38 2021 daemon.notice netifd: Interface 'wan' has link connectivity
Sat Mar  6 16:57:38 2021 daemon.notice netifd: Interface 'wan' is setting up now
Sat Mar  6 16:57:38 2021 daemon.err insmod: module is already loaded - slhc
Sat Mar  6 16:57:38 2021 daemon.err insmod: module is already loaded - ppp_generic
Sat Mar  6 16:57:38 2021 daemon.err insmod: module is already loaded - pppox
Sat Mar  6 16:57:38 2021 daemon.err insmod: module is already loaded - pppoe
Sat Mar  6 16:57:38 2021 daemon.info pppd[7461]: Plugin rp-pppoe.so loaded.
Sat Mar  6 16:57:38 2021 daemon.info pppd[7461]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.8
Sat Mar  6 16:57:38 2021 daemon.notice pppd[7461]: pppd 2.4.8 started by root, uid 0
Sat Mar  6 16:57:38 2021 daemon.debug pppd[7461]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Sat Mar  6 16:57:38 2021 daemon.debug pppd[7461]:  dst ff:ff:ff:ff:ff:ff  src 00:0d:xx:xx:xx:xx
Sat Mar  6 16:57:38 2021 daemon.debug pppd[7461]:  [service-name] [host-uniq  25 1d 00 00]
Sat Mar  6 16:57:39 2021 user.notice nlbwmon: Reloading nlbwmon due to ifup of loopback (lo)
Sat Mar  6 16:57:40 2021 user.notice firewall: Reloading firewall due to ifup of wg0 (wg0)
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  dst ff:ff:ff:ff:ff:ff  src 00:0d:xx:xx:xx:xx
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  [service-name] [host-uniq  25 1d 00 00]
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 48
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  dst 00:0d:b9:41:45:60  src 24:21:xx:xx:xx:xx
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  [service-name] [AC-name <redacted>] [host-uniq  25 1d 00 00] [AC-cookie  0a 47 32 c6 af a0 98 80 be c4 21 97 69 5a c1 a8]
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  dst 24:21:24:91:b7:82  src 00:0d:xx:xx:xx:xx
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  [service-name] [host-uniq  25 1d 00 00] [AC-cookie  0a 47 32 c6 af a0 98 80 be c4 21 97 69 5a c1 a8]
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: Recv PPPOE Discovery V1T1 PADS session 0x1 length 12
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  dst 00:0d:b9:41:45:60  src 24:21:xx:xx:xx:xx
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]:  [service-name] [host-uniq  25 1d 00 00]
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: PADS: Service-Name: ''
Sat Mar  6 16:57:43 2021 daemon.info pppd[7461]: PPP session is 1
Sat Mar  6 16:57:43 2021 daemon.warn pppd[7461]: Connected to 24:21:xx:xx:xx:xx via interface eth0
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: using channel 6
Sat Mar  6 16:57:43 2021 kern.info kernel: [   82.413122] pppoe-wan: renamed from ppp0
Sat Mar  6 16:57:43 2021 daemon.info pppd[7461]: Renamed interface ppp0 to pppoe-wan
Sat Mar  6 16:57:43 2021 daemon.info pppd[7461]: Using interface pppoe-wan
Sat Mar  6 16:57:43 2021 daemon.notice pppd[7461]: Connect: pppoe-wan <--> eth0
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x21b969dd>]
Sat Mar  6 16:57:43 2021 daemon.debug pppd[7461]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x21b969dd>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [LCP ConfReq id=0x25 <mru 1492> <auth chap MD5> <magic 0x39bd4ef8>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [LCP ConfAck id=0x25 <mru 1492> <auth chap MD5> <magic 0x39bd4ef8>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [LCP EchoReq id=0x0 magic=0x21b969dd]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [CHAP Challenge id=0x1 <ef40198fab3412cd32c21c659920c12dd4fd60c1d86d96cdd9d167a845e1df35237844cead579cdf9938c4b25886e02d84c06eddad>, name = "<redacted>"]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [CHAP Response id=0x1 <211a16fc6fa0f717dd36d9be48cba294>, name = "<redacted>"]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [LCP EchoRep id=0x0 magic=0x39bd4ef8]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [CHAP Success id=0x1 "QOS"]
Sat Mar  6 16:57:45 2021 daemon.info pppd[7461]: CHAP authentication succeeded: QOS
Sat Mar  6 16:57:45 2021 daemon.notice pppd[7461]: CHAP authentication succeeded
Sat Mar  6 16:57:45 2021 daemon.notice pppd[7461]: peer from calling number 24:21:xx:xx:xx:xx authorized
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [IPV6CP ConfReq id=0x1 <addr fe80::400d:ae73:98e8:4694>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPV6CP ConfReq id=0xf <addr fe80::2621:24ff:fe91:b63f>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [IPV6CP ConfAck id=0xf <addr fe80::2621:24ff:fe91:b63f>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPCP ConfReq id=0x47 <addr xx.xx.xx.xx>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [IPCP ConfAck id=0x47 <addr xx.xx.xx.xx>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPCP ConfNak id=0x1 <addr xx.xx.xx.xx> <ms-dns1 xx.xx.xx.xx> <ms-dns2 xx.xx.xx.xx>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [IPCP ConfReq id=0x2 <addr xx.xx.xx.xx> <ms-dns1 xx.xx.xx.xx> <ms-dns2 xx.xx.xx.xx>]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPV6CP ConfAck id=0x1 <addr fe80::400d:ae73:98e8:4694>]
Sat Mar  6 16:57:45 2021 daemon.err pppd[7461]: sif6addr: ioctl(SIOCSIFADDR): Permission denied (line 2848)
Sat Mar  6 16:57:45 2021 daemon.warn pppd[7461]: sif6addr failed
Sat Mar  6 16:57:45 2021 daemon.warn pppd[7461]: cif6addr: ioctl(SIOCDIFADDR): No such address
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [IPV6CP TermReq id=0x2 "Interface configuration failed"]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPCP ConfAck id=0x2 <addr xx.xx.xx.xx> <ms-dns1 xx.xx.xx.xx> <ms-dns2 xx.xx.xx.xx>]
Sat Mar  6 16:57:45 2021 daemon.notice pppd[7461]: local  IP address xx.xx.xx.xx
Sat Mar  6 16:57:45 2021 daemon.notice pppd[7461]: remote IP address xx.xx.xx.xx
Sat Mar  6 16:57:45 2021 daemon.notice pppd[7461]: primary   DNS address xx.xx.xx.xx
Sat Mar  6 16:57:45 2021 daemon.notice pppd[7461]: secondary DNS address xx.xx.xx.xx
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: Script /lib/netifd/ppp-up started (pid 7752)
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [LCP TermReq id=0x26]
Sat Mar  6 16:57:45 2021 daemon.info pppd[7461]: LCP terminated by peer
Sat Mar  6 16:57:45 2021 daemon.info pppd[7461]: Connect time 0.0 minutes.
Sat Mar  6 16:57:45 2021 daemon.info pppd[7461]: Sent 0 bytes, received 4 bytes.
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [LCP TermAck id=0x26]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPV6CP TermAck id=0x2]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: Discarded non-LCP packet when LCP not open
Sat Mar  6 16:57:45 2021 daemon.notice netifd: Interface 'wan' is now up
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: Script /lib/netifd/ppp-up finished (pid 7752), status = 0x1
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: Script /lib/netifd/ppp-down started (pid 7756)
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' has lost the connection
Sat Mar  6 16:57:46 2021 daemon.debug pppd[7461]: Script /lib/netifd/ppp-down finished (pid 7756), status = 0x1
Sat Mar  6 16:57:46 2021 daemon.notice pppd[7461]: Modem hangup
Sat Mar  6 16:57:46 2021 daemon.notice pppd[7461]: Connection terminated.
Sat Mar  6 16:57:46 2021 daemon.debug pppd[7461]: Send PPPOE Discovery V1T1 PADT session 0x1 length 28
Sat Mar  6 16:57:46 2021 daemon.debug pppd[7461]:  dst 24:21:xx:xx:xx:xx  src 00:0d:xx:xx:xx:xx
Sat Mar  6 16:57:46 2021 daemon.debug pppd[7461]:  [host-uniq  25 1d 00 00] [AC-cookie  0a 47 32 c6 af a0 98 80 be c4 21 97 69 5a c1 a8]
Sat Mar  6 16:57:46 2021 daemon.info pppd[7461]: Sent PADT
Sat Mar  6 16:57:46 2021 daemon.info pppd[7461]: Exit.
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' is now down
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' is disabled
Sat Mar  6 16:57:46 2021 kern.info kernel: [   85.440614] 8021q: adding VLAN 0 to HW filter on device eth0
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' is enabled
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' is setting up now
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Network device 'eth0' link is down
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' has link connectivity loss
Sat Mar  6 16:57:46 2021 daemon.err insmod: module is already loaded - slhc
Sat Mar  6 16:57:46 2021 daemon.err insmod: module is already loaded - ppp_generic
Sat Mar  6 16:57:46 2021 daemon.err insmod: module is already loaded - pppox
Sat Mar  6 16:57:46 2021 daemon.err insmod: module is already loaded - pppoe
Sat Mar  6 16:57:46 2021 daemon.notice netifd: wan (7779): Command failed: Permission denied
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' is now down
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' is disabled
Sat Mar  6 16:57:46 2021 daemon.notice netifd: Interface 'wan' is enabled
Sat Mar  6 16:57:46 2021 kern.info kernel: [   85.620546] 8021q: adding VLAN 0 to HW filter on device eth0

Thanks!

dl12345 · March 7, 2021, 2:18am

Borromini:

Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: sent [IPV6CP TermReq id=0x2 "Interface configuration failed"]
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [IPCP ConfAck id=0x2 <addr xx.xx.xx.xx> <ms-dns1 xx.xx.xx.xx> <ms-dns2 xx.xx.xx.xx>]
...
Sat Mar  6 16:57:45 2021 daemon.debug pppd[7461]: rcvd [LCP TermReq id=0x26]
Sat Mar  6 16:57:45 2021 daemon.info pppd[7461]: LCP terminated by peer

The answer is in your debug output. ipv6 interface configuration failed, so pppd asks the peer to terminate the session. Try and enable ipv6

Borromini · March 7, 2021, 10:36am

It's not, unfortunately. This is what I've tested (and what fails):

Re-enable IPv6 over PPPoE on 19.07 (breaks, see thread linked in first post)
Upgrade to a 21.02 snapshot, breaks as well with IPv6 still enabled
Disable IPv6 on 21.02, still breaks with the log above (and posted settings).

Worth noting might be that 21.02 still tried to bring up the wan6 interface without option auto '0', so I had to disable that as well compared to 19.07.

So yes, it still looks like there are IPv6 configuration attempts, despite it being turned off in the network configuration. Am I missing some (implicit) IPv6 options? Is there anything else I can turn off or extra settings I might be able to feed into /etc/ppp/options directly to test?

jow · July 3, 2021, 5:11pm

Try setting option pppd_options noipv6 - that should prevent any IPv6 configuration attempts. We probably should pass that to pppd automatically if "option ipv6 0" is specified.

Borromini · July 3, 2021, 5:17pm

Thanks jow, will try setting that and report back.

Edit: shouldn't have ticked jow's post as the solution, as I cannot reply to my own topic anymore now.

@jow I had the opportunity to upgrade the APU2 from 19.07 to 21.02 again; the noipv6 option did the trick. Thanks for the tip. Can it be added to the PPP setup by default? I looked through package/network/services/ppp/files/ppp.sh but I'm not familiar enough with the code to be sure where to add the extra PPP option.

system · July 14, 2021, 7:10pm

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.