Page MenuHomeVyOS Platform
Create Task
Maniphest T2248

PPPoE Broken in Latest 1.3 Rolling (1.3-rolling-202004070629)
Closed, ResolvedPublicBUG
Actions

Description

Hi,

PPPoE establishes fine in 1.3-rolling-202004030632

Trying to establish PPPoE in 1.3-rolling-202004070629 gives me the following logs (greping for ppp in /var/log/messages)

Apr  8 18:18:08 localhost systemd[1]: Starting Restore /etc/resolv.conf if the system crashed before the ppp link was shut down...
Apr  8 18:18:08 localhost systemd[1]: pppd-dns.service: Succeeded.
Apr  8 18:18:08 localhost systemd[1]: Started Restore /etc/resolv.conf if the system crashed before the ppp link was shut down.
Apr  8 18:18:45 ferrari systemd[1]: Created slice system-ppp.slice.
Apr  8 18:18:45 ferrari systemd[1]: Started Dialing PPP connection pppoe0.
Apr  8 18:18:45 ferrari pppd[1985]: Plugin rp-pppoe.so loaded.
Apr  8 18:18:46 ferrari netplugd[874]: ppp0: ignoring event
Apr  8 18:18:46 ferrari netplugd[874]: pppoe0: ignoring event
Apr  8 18:18:46 ferrari systemd-udevd[1990]: link_config: could not get ethtool features for ppp0
Apr  8 18:18:46 ferrari systemd-udevd[1990]: Could not set offload features of ppp0: No such device
Apr  8 18:18:46 ferrari netplugd[874]: pppoe0: ignoring event
Apr  9 06:18:49 ferrari ntpd[2043]: Listen normally on 4 pppoe0 10.64.64.64:123
Apr  9 06:22:46 ferrari pppd[1985]: Terminating on signal 15
Apr  9 06:22:46 ferrari netplugd[874]: pppoe0: ignoring event
Apr  9 06:22:46 ferrari pppd[1985]: Exit.
Apr  9 06:22:46 ferrari netplugd[874]: pppoe0: ignoring event
Apr  9 06:22:46 ferrari systemd[1]: [email protected]: Main process exited, code=exited, status=5/NOTINSTALLED
Apr  9 06:22:46 ferrari systemd[1]: [email protected]: Failed with result 'exit-code'.
Apr  9 06:22:47 ferrari ntpd[2043]: Deleting interface #4 pppoe0, 10.64.64.64#123, interface stats: received=0, sent=0, dropped=0, active_time=238 secs
Apr  9 06:22:51 ferrari systemd[1]: [email protected]: Service RestartSec=5s expired, scheduling restart.
Apr  9 06:22:51 ferrari systemd[1]: [email protected]: Scheduled restart job, restart counter is at 1.
Apr  9 06:22:51 ferrari systemd[1]: Stopped Dialing PPP connection pppoe0.
Apr  9 06:22:51 ferrari systemd[1]: Started Dialing PPP connection pppoe0.
Apr  9 06:22:51 ferrari pppd[3607]: Plugin rp-pppoe.so loaded.
Apr  9 06:22:51 ferrari pppd[3607]: Plugin rp-pppoe.so loaded.
Apr  9 06:22:51 ferrari pppd[3607]: pppd 2.4.7 started by root, uid 0
Apr  9 06:22:51 ferrari netplugd[874]: ppp0: ignoring event
Apr  9 06:22:51 ferrari kernel: [  303.700969] pppoe0: renamed from ppp0
Apr  9 06:22:51 ferrari pppd[3607]: Renamed interface ppp0 to pppoe0
Apr  9 06:22:51 ferrari pppd[3607]: Using interface pppoe0
Apr  9 06:22:51 ferrari netplugd[874]: pppoe0: ignoring event
Apr  9 06:22:51 ferrari systemd-udevd[3608]: link_config: could not get ethtool features for ppp0
Apr  9 06:22:51 ferrari systemd-udevd[3608]: Could not set offload features of ppp0: No such device
Apr  9 06:22:51 ferrari pppd[3607]: executing /etc/ppp/ip-pre-up.d/1000-vyos-pppoe-pppoe0
Apr  9 06:22:51 ferrari pppd[3607]: local  IP address 10.64.64.64
Apr  9 06:22:51 ferrari pppd[3607]: remote IP address 10.112.112.112
Apr  9 06:22:51 ferrari netplugd[874]: pppoe0: ignoring event
Apr  9 06:22:53 ferrari ntpd[2043]: Listen normally on 10 pppoe0 10.64.64.64:123
Apr  9 06:22:53 ferrari pppd[3607]: Terminating on signal 15
Apr  9 06:22:53 ferrari netplugd[874]: pppoe0: ignoring event
Apr  9 06:22:53 ferrari pppd[3607]: Exit.
Apr  9 06:22:53 ferrari netplugd[874]: pppoe0: ignoring event
Apr  9 06:22:53 ferrari systemd[1]: [email protected]: Main process exited, code=exited, status=5/NOTINSTALLED
Apr  9 06:22:53 ferrari systemd[1]: [email protected]: Failed with result 'exit-code'.
Apr  9 06:22:55 ferrari ntpd[2043]: Deleting interface #10 pppoe0, 10.64.64.64#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs
Apr  9 06:22:58 ferrari systemd[1]: [email protected]: Service RestartSec=5s expired, scheduling restart.
Apr  9 06:22:58 ferrari systemd[1]: [email protected]: Scheduled restart job, restart counter is at 2.
Apr  9 06:22:58 ferrari systemd[1]: Stopped Dialing PPP connection pppoe0.
Apr  9 06:22:58 ferrari systemd[1]: Started Dialing PPP connection pppoe0.
Apr  9 06:22:58 ferrari pppd[3757]: Plugin rp-pppoe.so loaded.
Apr  9 06:22:58 ferrari pppd[3757]: Plugin rp-pppoe.so loaded.
Apr  9 06:22:58 ferrari pppd[3757]: pppd 2.4.7 started by root, uid 0

Logs from working PPPoE in 1.3-rolling-202004030632 (note some IP's and MAC's have been X'd)

[email protected]:/var/log# grep ppp messages
Apr  9 06:25:28 ferrari systemd[1]: Starting Restore /etc/resolv.conf if the system crashed before the ppp link was shut down...
Apr  9 06:25:28 ferrari systemd[1]: pppd-dns.service: Succeeded.
Apr  9 06:25:28 ferrari systemd[1]: Started Restore /etc/resolv.conf if the system crashed before the ppp link was shut down.
Apr  9 06:26:08 ferrari systemd[1]: Created slice system-ppp.slice.
Apr  9 06:26:08 ferrari systemd[1]: Started Dialing PPP connection pppoe0.
Apr  9 06:26:08 ferrari pppd[1912]: Plugin rp-pppoe.so loaded.
Apr  9 06:26:08 ferrari pppd[1912]: Plugin rp-pppoe.so loaded.
Apr  9 06:26:08 ferrari pppd[1912]: pppd 2.4.7 started by root, uid 0
Apr  9 06:26:08 ferrari netplugd[819]: ppp0: ignoring event
Apr  9 06:26:08 ferrari kernel: [   55.575710] pppoe0: renamed from ppp0
Apr  9 06:26:08 ferrari pppd[1912]: Renamed interface ppp0 to pppoe0
Apr  9 06:26:08 ferrari pppd[1912]: Using interface pppoe0
Apr  9 06:26:08 ferrari netplugd[819]: pppoe0: ignoring event
Apr  9 06:26:08 ferrari systemd-udevd[1916]: link_config: could not get ethtool features for ppp0
Apr  9 06:26:08 ferrari systemd-udevd[1916]: Could not set offload features of ppp0: No such device
Apr  9 06:26:08 ferrari pppd[1912]: local  IP address 10.64.64.64
Apr  9 06:26:08 ferrari pppd[1912]: remote IP address 10.112.112.112
Apr  9 06:26:08 ferrari netplugd[819]: pppoe0: ignoring event
Apr  9 06:26:08 ferrari pppd[1912]: Starting link
Apr  9 06:26:08 ferrari pppd[1912]: PPP session is 336
Apr  9 06:26:08 ferrari pppd[1912]: Connected to XX:XX:XX:XX:26:01 via interface eth0
Apr  9 06:26:08 ferrari pppd[1912]: Connect: pppoe0 <--> eth0
Apr  9 06:26:11 ferrari pppd[1912]: Remote message: Login ok
Apr  9 06:26:11 ferrari pppd[1912]: PAP authentication succeeded
Apr  9 06:26:11 ferrari pppd[1912]: peer from calling number XX:XX:XX:XX:26:01 authorized
Apr  9 06:26:11 ferrari pppd[1912]: Local IP address changed to x.x.x.17
Apr  9 06:26:11 ferrari pppd[1912]: Remote IP address changed to x.x.x.251
Apr  9 06:26:11 ferrari ntpd[1972]: Listen normally on 4 pppoe0 x.x.x.17:123
Apr  9 06:26:12 ferrari pppd[1912]: Open TCP x.x.x.17:34568 -> x.x.x.59:443
Apr  9 06:26:12 ferrari pppd[1912]: executing /etc/ppp/ip-up.d/9990-vyos-vrf-pppoe0
Apr  9 06:26:57 ferrari openvpn-vtun2[2402]: ROUTE_GATEWAY ON_LINK IFACE=pppoe0 HWADDR=00:00:00:00:00:00

Thanks,
Tim

Details

Difficulty level
Unknown (require assessment)
Version
1.3-rolling-202004070629
Why the issue appeared?
Will be filled on close
Is it a breaking change?
Perfectly compatible
Issue type
Bug (incorrect behavior)

Related Objects

Event Timeline

tjh created this task.Apr 8 2020, 8:11 PM

The only major differences I've noticed are the kernel versions:

1.3-rolling-202004030632 (works): 4.19.112-amd64-vyos
1.3-rolling-202004070629 (fails): 4.19.114-amd64-vyos

c-po claimed this task.Apr 8 2020, 8:36 PM

Can you please share your configuration on the pppoe interface with us?

c-po added a project: VyOS 1.3 Equuleus.Apr 8 2020, 8:45 PM
c-po added a comment.Apr 8 2020, 8:49 PM

I can't reproduce it with the code in the rolling image that will be available by tomorrow.

image.png (171×305 px, 5 KB)

Please share your config and retest with rolling 1.3-rolling-20200409*

tjh added a comment.Apr 8 2020, 8:50 PM

Certainly.

Please find below, with some comments redacted.

[edit]
[email protected]# show interfaces ethernet eth0
 description "WAN Interface to Fibre Provider ONT"
 mac 4c:55:56:44:41:4e
 mtu 9000
 smp-affinity auto

[edit]
[email protected]# show interfaces pppoe pppoe0
 authentication {
     password doesntmatter
     user [email protected]
 }
 connect-on-demand
 default-route auto
 description "PPPoE To <my ISP>"
 firewall {
     in {
         name WAN-IN
     }
     local {
         name WAN-LOCAL
     }
 }
 mtu 1500
 source-interface eth0
 traffic-policy {
     out shape-17mbit
 }
[edit]
[email protected]#

You will note a couple of things:

  1. I am using pppoe0 instead of pppoe1. The ? help seems to imply that the first PPP interface must be named 1, but 0 appears to work and is consistent with other interfaces, so that's why I am using pppoe0.
  1. I am spoofing the MAC address source all packets from on eth0. This is because my friend Dan works at my ISP and that MAC address, converted from HEX to ASCII, reads LUVDAN. It's the small things I find humour in.

Thanks!

tjh updated the task description. (Show Details)Apr 8 2020, 9:25 PM
pasik added a subscriber: pasik.Apr 9 2020, 7:48 AM
c-po added a comment.EditedApr 9 2020, 10:20 AM

Hello @tjh,

the Problem comes with the connect-on-demand option. As the default route setup was changed some days ago by me to support PPPoE for VRFs this introduced a regression (T2219).

In your log's you see:

Apr  9 06:22:51 ferrari pppd[3607]: local  IP address 10.64.64.64
Apr  9 06:22:51 ferrari pppd[3607]: remote IP address 10.112.112.112

This is the IP address assigned to the PPPoE interface when it is configured for dial-on-demand. A default route is configured to throw all packets down that link which will cause the dialing process. Unfortunately that route is no longer installed in the dial-on-demand corner case.

As workaround you should remove the connect-on-demand option.

tjh added a comment.EditedApr 9 2020, 6:54 PM

Thank you @c-po - I can confirm removal of connect-on-demand fixes the problem.
I was under the, obviously mistaken, impression that I needed that command for PPPoE to self-establish on reboot. But I obviously don't as I've just rebooted with the latest 1.3-rolling-202004090909 and it's connected straight away and is working.

Thank you for your prompt assistance.

c-po closed this task as Resolved.Apr 10 2020, 11:31 AM
c-po changed Is it a breaking change? from Behavior change to Perfectly compatible.
c-po added a comment.Apr 10 2020, 11:33 AM

on-demand dialing and VRFs are now mutually exlcusive. As VRF is a new feature of 1.3 this won't break existing 1.2 LTS devices.

To make on-demand dialing and VRFs to work properly the VRF functionality should be implemented in PPP so it places the interface into a VRF by itsef - but I guess on-demand dialing and VRF together are a super rare use-case nowadays as almost every PPPoE connection is now based on (unlimited-)traffic rather then time.

c-po moved this task from Need Triage to Finished on the VyOS 1.3 Equuleus board.May 21 2020, 5:24 PM
erkin set Issue type to Bug (incorrect behavior).Aug 30 2021, 7:23 AM
erkin removed a subscriber: Active contributors.
syncer edited projects, added VyOS 1.3 Equuleus (1.3.0); removed VyOS 1.3 Equuleus.Aug 30 2022, 2:01 PM
syncer moved this task from Need Triage to Finished on the VyOS 1.3 Equuleus (1.3.0) board.