New PPPoE backend, some feedback

stephenw10

Hmm, does it just show incrementing retries? I've seen it take 5 or 6 retries whch take 30s or so for my connection. But not longer than that.

RobbieTT

@stephenw10 said in New PPPoE backend, some feedback:

what does pppcfg show at that point, after the initial 'connect' in the gui?

It shows nothing and stops taking commands. When it finally works:

[25.03-BETA][admin@Router-7.xxxx.me]/root: pppcfg pppoe0
	dev: igc0 state: session
	sid: 0x11b4 PADI retries: 0 PADR retries: 0 time: 00:46:38
	sppp: phase network authproto auto authname "FTTP.xxxxx@idnet" peerproto auto 
	dns: 212.69.40.23 212.69.36.23

Not helpful I know.

When the GUI 'hangs' for a bit I then get the ever-helpful busy message:

2025-04-25 at 14.37.31-GUI droped.png

Hopefully the log may be of more help.

️

stephenw10

Huh, it just returns nothing immediately? Or appears to hang waiting for something?

Returning nothing is what it does when the interface is down, before you click 'connect'. Usually!

RobbieTT

@stephenw10

As in the SSH connection stalls so nothing to access. I'm not best placed to stick the console cable in etc.

Anything useful in the system log I sent?

️

stephenw10

Nothing really jumps out. Except maybe the fact you have a 10M USB NIC connected. Which makes me twitch but probably isn't related.

During that time you disconnected and attempted to reconnect from the Interfaces Status page? And it failed connect?

RobbieTT

@stephenw10 said in New PPPoE backend, some feedback:

Nothing really jumps out. Except maybe the fact you have a 10M USB NIC connected. Which makes me twitch but probably isn't related.

I may be missing something here but there is no USB NIC connected to my pfSense system. Just a DAC and an RJ45:

It's the blue lighting that makes it fast of course.

️

stephenw10

It's probably an IPMI device then. If I had to guess.

RobbieTT

@stephenw10 said in New PPPoE backend, some feedback:

It's probably an IPMI device then. If I had to guess.

It does have an Aspeed IPMI and the BMC has a dedicated LAN port (not currently in use).

️

RobbieTT

@stephenw10 said in New PPPoE backend, some feedback:

During that time you disconnected and attempted to reconnect from the Interfaces Status page? And it failed connect?

After the first reconnection attempt it just went around in that loop so the 'hotplug' events are all self-generated. Quite a few services and packages were also trying to start before it was possible to do so with the pppoe state.

Other oddities include waiting on Tailscale which, whilst installed, is actually disabled and services not finding ports available, failing, restarting, then all packages restarting etc. This also included unbound, pfBlocker, Avahi, vnstatd, php, IPSec tunnels and OpenVPN (also not in use) and the kernel not happy about 'Media change is not supported' etc. I'm presuming the startup sequence has changed little but perhaps with the pppoe change it's just tying itself in knots?

It's all a bit random and messy but nothing that looks like an obvious cause. It still feels like a race condition though. Doing either a cold boot or a reboot has (so far) had no such issues. Just taking the pope interface down and back up again triggers it all.

Maybe the fix applied for the previous pppoe race condition for the older mpd5 pppoe backend has become undone?

️

stephenw10

Your logs don't include the boot sequence so it only shown as something vnstat is monitoring:
vnstatd 12727 Monitoring (13): ue0 (10 Mbit)

The logs also show that some of the NICs actually lost link like:

Apr 25 13:03:38	kernel		ice0.1003: link state changed to DOWN
Apr 25 13:03:38	kernel		ice0: link state changed to DOWN

Was that you unplugging/rebooting something?

RobbieTT

@stephenw10 said in New PPPoE backend, some feedback:

Was that you unplugging/rebooting something?

No, not touching anything, it's all self generated issues as it ties itself in knots for either a short period or a very long one.

For now, a full reboot is the most reliable method of connecting PPPoE (connecting on first attempt) and often it is much faster than taking the interface down and up again, as I would normally do.

Outside of this weird bug or race condition the new PPPoE backend is very impressive. The CPU even runs a bit cooler when ticking over with background traffic at night.

I've little time for proper testing (my wife is ill) but if there is something specific you would like me to run or capture then I will do my best to do so, when I need the distraction. Exact commands that I can paste in with little thought would be ideal.

️

stephenw10

Hmm, OK.

If you can try to grab a packet capture on the parent NIC when it's failing to connect. Just to make sure it really is trying or if something low level is preventing it.

RobbieTT

@stephenw10 said in New PPPoE backend, some feedback:

Hmm, OK.

If you can try to grab a packet capture on the parent NIC when it's failing to connect. Just to make sure it really is trying or if something low level is preventing it.

I've sent you some, as requested.

️

MichielHN

I tried 2.8/ if_pppoe module on my kpn wan. IPv4 performs as normal, not noticeable faster. IPv6 doesn’t work.
Any idea’s?
2.8/old mds functions as before

RobbieTT

@MichielHN

Any improvement when you do a full reboot?

Any change when using ISC DHCP rather than Kea DHCP (I've always struggled with Kea to date)?

️

stephenw10

Using Kea or ISC should have no effect on the dhcpv6 client side.

Do you see log entries for that like:

Apr 28 21:13:35 	dhcp6c 	48726 	Sending Solicit
Apr 28 21:13:36 	dhcp6c 	48726 	Sending Request
Apr 28 21:13:36 	dhcp6c 	48726 	unknown or unexpected DHCP6 option opt_82, len 4
Apr 28 21:13:36 	dhcp6c 	48726 	dhcp6c Received REQUEST
Apr 28 21:13:36 	dhcp6c 	48726 	add an address 2001:db8::553/128 on pppoe0

What is shown in the system log when the PPPoE link connects?

MichielHN

@stephenw10

Apr 29 07:43:42 kea-dhcp6 37506 ERROR [kea-dhcp6.packets.0x1c23f9c15f00] DHCP6_PACKET_SEND_FAIL duid=[00:01:00:01:25:1d:ef:50:98:fa:9b:be:60:df], [no hwaddr info], tid=0xb0d2f9: failed to send DHCPv6 packet: pkt6 send failed: sendmsg() returned with an error: Permission denied
Apr 29 07:43:39 kea2unbound 72873 Unbound reloaded: /var/unbound/unbound.conf
Apr 29 07:43:39 kea2unbound 72873 Include updated: /var/unbound/leases/leases6.conf (e6c272f98c398a24)
Apr 29 07:43:39 kea2unbound 72873 Unbound lease include is missing or inconsistent: /var/unbound/leases/leases6.conf
Apr 29 07:43:37 kea2unbound 36816 Unbound reloaded: /var/unbound/unbound.conf
Apr 29 07:43:37 kea2unbound 36816 Include updated: /var/unbound/leases/leases4.conf (e6c272f98c398a24)
Apr 29 07:43:37 kea2unbound 36816 Unbound lease include is missing or inconsistent: /var/unbound/leases/leases4.conf
Apr 29 07:43:37 kea-dhcp6 37506 WARN [kea-dhcp6.dhcp6.0x1c23f9c12000] DHCP6_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:43:37 kea-dhcp6 37506 WARN [kea-dhcp6.dhcp6.0x1c23f9c12000] DHCP6_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:43:37 kea-dhcp6 37506 WARN [kea-dhcp6.dhcpsrv.0x1c23f9c12000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Apr 29 07:43:37 kea-dhcp4 35883 WARN [kea-dhcp4.dhcp4.0x358c42a12000] DHCP4_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:43:37 kea-dhcp4 35883 WARN [kea-dhcp4.dhcp4.0x358c42a12000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:43:37 kea-dhcp4 35883 WARN [kea-dhcp4.dhcpsrv.0x358c42a12000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Apr 29 07:43:35 dhcp6c 1363 status code for PD-0: success
Apr 29 07:43:35 dhcp6c 1363 add an address 2a02:a45b:XX:fe54:3303/64 on lagg0.20
Apr 29 07:43:35 dhcp6c 1363 add an address 2a02:a45b:XX:fe54:3303/64 on lagg0
Apr 29 07:43:35 dhcp6c 1363 add an address 2a02:a45b:XX:fe54:3300/64 on igb0
Apr 29 07:43:35 dhcp6c 1363 dhcp6c Received REQUEST
Apr 29 07:43:35 dhcp6c 1363 Sending Request
Apr 29 07:43:34 dhcp6c 1363 Sending Solicit
Apr 29 07:43:33 dhcp6c 1069 skip opening control port
Apr 29 07:43:33 dhcp6c 1069 failed initialize control message authentication
Apr 29 07:43:33 dhcp6c 1069 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 07:43:26 kea2unbound 91866 Unbound reloaded: /var/unbound/unbound.conf
Apr 29 07:43:26 kea2unbound 91866 Include updated: /var/unbound/leases/leases4.conf (bc15803b5f83e2c4)
Apr 29 07:43:26 kea2unbound 91866 Unbound lease include is missing or inconsistent: /var/unbound/leases/leases4.conf
Apr 29 07:43:23 dhcp6c 78256 exiting
Apr 29 07:43:23 dhcp6c 81124 script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 07:43:23 dhcp6c 81124 lstat failed: No such file or directory
Apr 29 07:43:23 dhcp6c 78256 exit without release
Apr 29 07:43:23 dhcp6c 78169 skip opening control port
Apr 29 07:43:23 dhcp6c 78169 failed initialize control message authentication
Apr 29 07:43:23 dhcp6c 78169 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 07:43:13 dhcp6c 99593 exiting
Apr 29 07:43:13 dhcp6c 1239 script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 07:43:13 dhcp6c 1239 lstat failed: No such file or directory
Apr 29 07:43:13 dhcp6c 99593 exit without release
Apr 29 07:43:13 dhcp6c 99583 skip opening control port
Apr 29 07:43:13 dhcp6c 99583 failed initialize control message authentication
Apr 29 07:43:13 dhcp6c 99583 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 07:43:10 kea-dhcp6 51343 WARN [kea-dhcp6.dhcp6.0x2b47c8c12000] DHCP6_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:43:10 kea-dhcp6 51343 WARN [kea-dhcp6.dhcpsrv.0x2b47c8c12000] DHCPSRV_NO_SOCKETS_OPEN no interface configured to listen to DHCP traffic
Apr 29 07:43:10 kea-dhcp6 51343 WARN [kea-dhcp6.dhcp6.0x2b47c8c12000] DHCP6_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:43:10 kea-dhcp6 51343 WARN [kea-dhcp6.dhcpsrv.0x2b47c8c12000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Apr 29 07:43:10 kea-dhcp4 49889 WARN [kea-dhcp4.dhcp4.0x31f5ea212000] DHCP4_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:43:10 kea-dhcp4 49889 WARN [kea-dhcp4.dhcp4.0x31f5ea212000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:43:10 kea-dhcp4 49889 WARN [kea-dhcp4.dhcpsrv.0x31f5ea212000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Apr 29 07:43:03 dhcp6c 16713 exiting
Apr 29 07:43:03 dhcp6c 19629 script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 07:43:03 dhcp6c 19629 lstat failed: No such file or directory
Apr 29 07:43:03 dhcp6c 16713 exit without release
Apr 29 07:43:03 dhcp6c 16536 skip opening control port
Apr 29 07:43:03 dhcp6c 16536 failed initialize control message authentication
Apr 29 07:43:03 dhcp6c 16536 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 07:42:59 kea2unbound 80738 Include updated: /var/unbound/leases/leases6.conf (2d06800538d394c2)
Apr 29 07:42:59 kea2unbound 80738 Unbound lease include is missing or inconsistent: /var/unbound/leases/leases6.conf
Apr 29 07:42:59 kea2unbound 72960 Include updated: /var/unbound/leases/leases4.conf (2d06800538d394c2)
Apr 29 07:42:59 kea2fib6 76380 Route cache updated: /var/run/kea2fib6.cache
Apr 29 07:42:59 kea2fib6 76380 Route cache missing or inconsistent: /var/run/kea2fib6.cache
Apr 29 07:42:59 kea2unbound 72960 Unbound lease include is missing or inconsistent: /var/unbound/leases/leases4.conf
Apr 29 07:42:59 kea-dhcp6 73456 WARN [kea-dhcp6.dhcp6.0x3bbcb3e12000] DHCP6_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:42:59 kea-dhcp6 73456 WARN [kea-dhcp6.dhcpsrv.0x3bbcb3e12000] DHCPSRV_NO_SOCKETS_OPEN no interface configured to listen to DHCP traffic
Apr 29 07:42:59 kea-dhcp6 73456 WARN [kea-dhcp6.dhcp6.0x3bbcb3e12000] DHCP6_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:42:59 kea-dhcp6 73456 WARN [kea-dhcp6.dhcpsrv.0x3bbcb3e12000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Apr 29 07:42:59 kea-dhcp4 71564 WARN [kea-dhcp4.dhcp4.0xf5c612000] DHCP4_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:42:59 kea-dhcp4 71564 WARN [kea-dhcp4.dhcp4.0xf5c612000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:42:59 kea-dhcp4 71564 WARN [kea-dhcp4.dhcpsrv.0xf5c612000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Apr 29 07:42:53 dhcp6c 20483 exiting
Apr 29 07:42:53 dhcp6c 26187 script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 07:42:53 dhcp6c 26187 lstat failed: No such file or directory
Apr 29 07:42:53 dhcp6c 20483 exit without release
Apr 29 07:42:53 dhcp6c 20241 skip opening control port
Apr 29 07:42:53 dhcp6c 20241 failed initialize control message authentication
Apr 29 07:42:53 dhcp6c 20241 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 07:42:43 dhcp6c 98441 exiting
Apr 29 07:42:43 dhcp6c 9433 script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 07:42:43 dhcp6c 9433 lstat failed: No such file or directory
Apr 29 07:42:43 dhcp6c 98441 exit without release
Apr 29 07:42:42 dhcp6c 98410 skip opening control port
Apr 29 07:42:42 dhcp6c 98410 failed initialize control message authentication
Apr 29 07:42:42 dhcp6c 98410 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 07:42:32 dhcp6c 93377 exiting
Apr 29 07:42:32 dhcp6c 96773 script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 07:42:32 dhcp6c 96773 lstat failed: No such file or directory
Apr 29 07:42:32 dhcp6c 93377 exit without release
Apr 29 07:42:32 dhcp6c 93260 skip opening control port
Apr 29 07:42:32 dhcp6c 93260 failed initialize control message authentication
Apr 29 07:42:32 dhcp6c 93260 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 07:41:24 kea2unbound 30462 Unbound reloaded: /var/unbound/unbound.conf
Apr 29 07:41:24 kea2unbound 30462 Include updated: /var/unbound/leases/leases4.conf (fd5159c4d49f6919)
Apr 29 07:41:24 kea2unbound 30462 Unbound lease include is missing or inconsistent: /var/unbound/leases/leases4.conf
Apr 29 07:41:23 kea-dhcp6 30760 WARN [kea-dhcp6.dhcp6.0x9d20ce12000] DHCP6_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:41:23 kea-dhcp6 30760 WARN [kea-dhcp6.dhcp6.0x9d20ce12000] DHCP6_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:41:23 kea-dhcp6 30760 WARN [kea-dhcp6.dhcpsrv.0x9d20ce12000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.
Apr 29 07:41:23 kea-dhcp4 29556 WARN [kea-dhcp4.dhcp4.0x193665812000] DHCP4_MULTI_THREADING_INFO enabled: yes, number of threads: 4, queue size: 64
Apr 29 07:41:23 kea-dhcp4 29556 WARN [kea-dhcp4.dhcp4.0x193665812000] DHCP4_RESERVATIONS_LOOKUP_FIRST_ENABLED Multi-threading is enabled and host reservations lookup is always performed first.
Apr 29 07:41:23 kea-dhcp4 29556 WARN [kea-dhcp4.dhcpsrv.0x193665812000] DHCPSRV_MT_DISABLED_QUEUE_CONTROL disabling dhcp queue control when multi-threading is enabled.

Apr 29 07:43:35 php-fpm 435 /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. 'WANIX1_DHCP6'
Apr 29 07:43:35 php-fpm 435 /rc.newwanip: Gateway, NONE AVAILABLE
Apr 29 07:43:35 php-fpm 434 /rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WANIX1 [opt6].
Apr 29 07:43:35 php-fpm 434 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0 due to REQUEST.
Apr 29 07:43:35 avahi-daemon 19906 Joining mDNS multicast group on interface lagg0.20.IPv6 with address 2a02:a45b:XXXX:3303.
Apr 29 07:43:35 avahi-daemon 19906 Leaving mDNS multicast group on interface lagg0.20.IPv6 with address fe80::1:1.
Apr 29 07:43:35 avahi-daemon 19906 Joining mDNS multicast group on interface lagg0.IPv6 with address 2a02:a45b:XXXX:3303.
Apr 29 07:43:35 avahi-daemon 19906 Leaving mDNS multicast group on interface lagg0.IPv6 with address fe80::1:1.
Apr 29 07:43:35 avahi-daemon 19906 Joining mDNS multicast group on interface igb0.IPv6 with address 2a02:a45b:XXX:3300.
Apr 29 07:43:35 avahi-daemon 19906 Leaving mDNS multicast group on interface igb0.IPv6 with address fe80::1:1.
Apr 29 07:43:34 php-fpm 435 /rc.newwanip: rc.newwanip: on (IP address: 82.X.X.187) (interface: WANIX1[opt6]) (real interface: pppoe0).
Apr 29 07:43:34 php-fpm 435 /rc.newwanip: rc.newwanip: Info: starting on pppoe0.
Apr 29 07:43:33 php 99763 /usr/local/sbin/ppp-ipv6: Starting rtsold process on opt6(pppoe0)
Apr 29 07:43:33 php 99763 /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode
Apr 29 07:43:33 php 99763 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
Apr 29 07:43:33 check_reload_status 474 rc.newwanip starting pppoe0
Apr 29 07:43:33 kernel pppoe0: link state changed to UP
Apr 29 07:43:26 arpwatch 67823 flip flop 0.0.0.0 10:63:c8:5e:75:cf (98:59:7a:a2:52:92)
Apr 29 07:43:25 rtsold 86419 <interface_up> pppoe0 does not accept Router Advertisement.
Apr 29 07:43:23 php-cgi 79473 pppoe-handler: HOTPLUG event: Invalid IP address
Apr 29 07:43:23 php 76803 /usr/local/sbin/ppp-ipv6: Starting rtsold process on opt6(pppoe0)
Apr 29 07:43:23 php 76803 /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode
Apr 29 07:43:23 php 76803 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
Apr 29 07:43:23 kernel pppoe0: link state changed to DOWN
Apr 29 07:43:23 kernel pppoe0: link state changed to UP
Apr 29 07:43:15 ntopng 15931 29/Apr/2025 07:43:15 [boot.lua:25] WARNING: No connectivity detected, ntopng will run in offline mode
Apr 29 07:43:15 ntopng 15931 29/Apr/2025 07:43:15 [boot.lua:23] [connectivity_utils.lua:64] WARNING: Connectivity check failed [Used https://github.com]
Apr 29 07:43:15 ntopng 22270 29/Apr/2025 07:43:15 [Ntop.cpp:265] ERROR: Another ntopng instance is running...
Apr 29 07:43:15 rtsold 38781 <interface_up> pppoe0 does not accept Router Advertisement.
Apr 29 07:43:15 php_pfb 30203 [pfBlockerNG] filterlog daemon started

MichielHN

@RobbieTT

thanks for your advise

Reboot sadly didn't solve the problem.
Part of trying the 2.8.0-Beta with the new if_pppoe kernel module would be sharing the problems i encounter during this update. Testing it on/with my personal hardware/isp.
I'm not a computer expert or programmer. I run pfsense on a sophos system. I think that would make me the ideal real life beta-tester :)

Michiel

bananajoe

@MichielHN
Could you please share the output of

netstat -r

This shows the routing table. I had same issue, but after setting default route for IPv6 all fine now.

BR

MichielHN

@bananajoe

it rather a long list; the items concerning pppoe are:

Shell Uitvoer - netstat -r | grep pppoe
default 195-XXX-XXX-121.fi UG pppoe0
195-XXX-XXX-121.fi link#22 UH pppoe0
default fe80::XXXX:XXXX:fe UG pppoe0
fe80::%pppoe0/64 link#22 U pppoe0