New PPPoE backend, some feedback
-
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 DOWNWas that you unplugging/rebooting something?
-
@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.
️ -
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.
-
@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.
️ -
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
-
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)?
️ -
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 pppoe0What is shown in the system log when the PPPoE link connects?
-
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 -
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
-
@MichielHN
Could you please share the output ofnetstat -rThis shows the routing table. I had same issue, but after setting default route for IPv6 all fine now.
BR
-
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 -
@MichielHN
Ok, there is no default route for IPv6.
Either you set the IPv6 GW fix, or build a static IPv6 route like this:
::/1 link#16 US pppoe1 -
@MichielHN
Show your pppoe wan config -
@MichielHN said in New PPPoE backend, some feedback:
@RobbieTT
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 :)It does indeed. I have a Netgate 6100 but I run the beta-testing on a modern bare-metal server to give real-world feedback, as Netgate have all the 6100's they need. Although they have been known to ask me to run stuff on my 6100 on occasion but I leave those decisions to them.
️ -
@bananajoe
setting IPv6 GW manually works fine, but i wonder what would happen if the isp decides to assign a different ipv6 range. -
@MichielHN
Different IPv6 range should be no problem, as the route is bound to the interface itself, not to the IPv6 address.
Should be dynamic. At least in my seatup it works great.PPPoE and 24h reset by ISP
-
@stephenw10 said in New PPPoE backend, some feedback:
I think the connection status you see is actually an artifact of the new interface type. I can sort of replicate what you see but in fact it does connect it's just not instant. You can see what the actual state is using the new
pppcfgcommand.
...
The actual time taken depends how fast the server responds. For be that be almost instant or it can be several retries and 20-30s.@stephenw10 commented on one of my (presumed) 'successful' connection attempts that I sent along with other pcaps. From the GUI it seemed to connect ok, within normal timeframes but looking in detail the PADI, PADO, PADR and PADS were all completed in around 6 ms (effectively instant). What then followed was repeated 'Configuration Requests' and the associated 'Ack' in response, stuck in a loop (in this case) for 20 sec.
In worst case examples this loop carries on for minutes and if or until it is resolved the dashboard shows the interface as 'Up' (but without details) and the Gateways show as 'Pending'. In this condition no WAN traffic is passed.
The redacted screenshot of the pcap is filtered on PPPoE activity alone:
️ -
Yeah that config delay seems odd. I'd expect that to be close to instant really. Though I guess some part of he upstream server might be delayed at the backend.
But the important part there would be whether or not it does eventually connect.
The old mpd5/netgraph pppoe client also shows as up if it's parent NIC is linked but if_pppoe, currently, shows as 'up' at all times one the interface is created. That's confusing the status page. It does seem like we could improve that relatively easily by including the connection state info there.
-
Try setting
Start DHCP6 client in debug modein System > Advanced > Networking.It's not clear from your dhcp logs whether or not it's actually running on pppoe0.
Also you can filter that log by the dhcp6c process. Everything else shown there isn't relevant.
-
@stephenw10 said in New PPPoE backend, some feedback:
Yeah that config delay seems odd. I'd expect that to be close to instant really. Though I guess some part of he upstream server might be delayed at the backend.
I did ponder that but pfSense asks the question and the upstream responds immediately with the correct Ack. There is nothing different in the multiple upstream server responses, even at the final time where pfSense stops asking, seemingly satisfied with the last repeated Ack.
Is there any chance the almost-paired PPP IPCP and PPP IPV6CP Requests are stepping on or resetting each other's almost-paired Acks?
In effect:
Request, Request, Ack, Ack = not good, loop continues
Request, Ack, Request, Ack = goodOnly the sequencing changes for the final accepted Acks, not the response Ack data. I know it shouldn't matter but it is the only difference I can find:
️
