New PPPoE backend, some feedback

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

bananajoe

@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

w0w

@MichielHN
Show your pppoe wan config

RobbieTT

@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.

️

MichielHN

@bananajoe
setting IPv6 GW manually works fine, but i wonder what would happen if the isp decides to assign a different ipv6 range.

@w0w
Schermafbeelding 2025-04-29 134640.jpg

bananajoe

@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

RobbieTT

@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 pppcfg command.
...
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:

2025-04-29 at 13.07.47.png

️

stephenw10

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.

stephenw10

@MichielHN

Try setting Start DHCP6 client in debug mode in 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.

RobbieTT

@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 = good

Only 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:

2025-04-29 at 15.03.33.png

️

MichielHN

@stephenw10

in the end there seems to be a response from pppoe but the gateway DHCP6 is still 'waiting'

the full 'grep dhcp6c /var/log/dhcpd.log' is too long to post

Apr 29 15:53:55 sofie dhcp6c[51825]: removing an event on pppoe0, state=INIT
Apr 29 15:53:55 sofie dhcp6c[51825]: executes /var/etc/dhcp6c_opt6_script.sh
Apr 29 15:53:55 sofie dhcp6c[53992]: lstat failed: No such file or directory
Apr 29 15:53:55 sofie dhcp6c[53992]: script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 15:53:55 sofie dhcp6c[51825]: script "/var/etc/dhcp6c_opt6_script.sh" terminated
Apr 29 15:53:55 sofie dhcp6c[51825]: exiting
Apr 29 15:54:05 sofie dhcp6c[18129]: extracted an existing DUID from /var/db/dhcp6c_duid: 00:01:00:01:2c:6d:3a:28:7c:5a:1c:54:33:00
Apr 29 15:54:05 sofie dhcp6c[18129]: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 15:54:05 sofie dhcp6c[18129]: failed initialize control message authentication
Apr 29 15:54:05 sofie dhcp6c[18129]: skip opening control port
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[interface] (9)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[pppoe0] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[send] (4)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[ia-pd] (5)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[0] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>comment [# request prefix delegation] (27)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[request] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[domain-name-servers] (19)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[request] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[domain-name] (11)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[script] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>["/var/etc/dhcp6c_opt6_script.sh"] (32)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>comment [# we'd like some nameservers please] (35)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[id-assoc] (8)
Apr 29 15:54:05 sofie dhcp6c[18129]: <13>[pd] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <13>[0] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <13>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[::] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[/] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[48] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[infinity] (8)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix-interface] (16)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[igb0] (4)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-id] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[0] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-len] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[16] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix-interface] (16)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[lagg0] (5)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-id] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[2] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-len] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[16] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix-interface] (16)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[lagg0.20] (8)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-id] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[32] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-len] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[16] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: called
Apr 29 15:54:05 sofie dhcp6c[18129]: called
Apr 29 15:54:05 sofie dhcp6c[18258]: reset a timer on pppoe0, state=INIT, timeo=0, retrans=891
Apr 29 15:54:06 sofie dhcp6c[18258]: Sending Solicit
Apr 29 15:54:06 sofie dhcp6c[18258]: a new XID (6c1ff3) is generated
Apr 29 15:54:06 sofie dhcp6c[18258]: set client ID (len 14)
Apr 29 15:54:06 sofie dhcp6c[18258]: set elapsed time (len 2)
Apr 29 15:54:06 sofie dhcp6c[18258]: set option request (len 4)
Apr 29 15:54:06 sofie dhcp6c[18258]: set IA_PD prefix
Apr 29 15:54:06 sofie dhcp6c[18258]: set IA_PD
Apr 29 15:54:06 sofie dhcp6c[18258]: send solicit to ff02::1:2%pppoe0
Apr 29 15:54:06 sofie dhcp6c[18258]: reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1091
Apr 29 15:54:06 sofie dhcp6c[18258]: receive advertise from fe80::9217:3fff:fe22:6263%pppoe0 on pppoe0
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option client ID, len 14
Apr 29 15:54:06 sofie dhcp6c[18258]: DUID: 00:01:00:01:2c:6d:3a:28:7c:5a:1c:54:33:00
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option server ID, len 14
Apr 29 15:54:06 sofie dhcp6c[18258]: DUID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option preference, len 1
Apr 29 15:54:06 sofie dhcp6c[18258]: preference: 0
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option IA_PD, len 54
Apr 29 15:54:06 sofie dhcp6c[18258]: IA_PD: ID=0, T1=86400, T2=138240
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option IA_PD prefix, len 25
Apr 29 15:54:06 sofie dhcp6c[18258]: IA_PD prefix: 2a02:a45b:e304::/48 pltime=172800 vltime=2292014193773376640
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option status code, len 9
Apr 29 15:54:06 sofie dhcp6c[18258]: status code: success
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option DNS, len 32
Apr 29 15:54:06 sofie dhcp6c[18258]: server ID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd, pref=0
Apr 29 15:54:06 sofie dhcp6c[18258]: reset timer for pppoe0 to 0.985017
Apr 29 15:54:07 sofie dhcp6c[18258]: picked a server (ID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd)
Apr 29 15:54:07 sofie dhcp6c[18258]: Sending Request
Apr 29 15:54:07 sofie dhcp6c[18258]: a new XID (f46830) is generated
Apr 29 15:54:07 sofie dhcp6c[18258]: set client ID (len 14)
Apr 29 15:54:07 sofie dhcp6c[18258]: set server ID (len 14)
Apr 29 15:54:07 sofie dhcp6c[18258]: set elapsed time (len 2)
Apr 29 15:54:07 sofie dhcp6c[18258]: set option request (len 4)
Apr 29 15:54:07 sofie dhcp6c[18258]: set IA_PD prefix
Apr 29 15:54:07 sofie dhcp6c[18258]: set status code
Apr 29 15:54:07 sofie dhcp6c[18258]: set IA_PD
Apr 29 15:54:07 sofie dhcp6c[18258]: send request to ff02::1:2%pppoe0
Apr 29 15:54:07 sofie dhcp6c[18258]: reset a timer on pppoe0, state=REQUEST, timeo=0, retrans=909
Apr 29 15:54:07 sofie dhcp6c[18258]: receive reply from fe80::9217:3fff:fe22:6263%pppoe0 on pppoe0
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option client ID, len 14
Apr 29 15:54:07 sofie dhcp6c[18258]: DUID: 00:01:00:01:2c:6d:3a:28:7c:5a:1c:54:33:00
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option server ID, len 14
Apr 29 15:54:07 sofie dhcp6c[18258]: DUID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option IA_PD, len 54
Apr 29 15:54:07 sofie dhcp6c[18258]: IA_PD: ID=0, T1=86400, T2=138240
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option IA_PD prefix, len 25
Apr 29 15:54:07 sofie dhcp6c[18258]: IA_PD prefix: 2a02:a45b:e304::/48 pltime=172800 vltime=2292014193773376640
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option status code, len 9
Apr 29 15:54:07 sofie dhcp6c[18258]: status code: success
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option DNS, len 32
Apr 29 15:54:07 sofie dhcp6c[18258]: dhcp6c Received REQUEST
Apr 29 15:54:07 sofie dhcp6c[18258]: nameserver[0] 2a02:a47f:e000::53
Apr 29 15:54:07 sofie dhcp6c[18258]: nameserver[1] 2a02:a47f:e000::54
Apr 29 15:54:07 sofie dhcp6c[18258]: make an IA: PD-0
Apr 29 15:54:07 sofie dhcp6c[18258]: create a prefix 2a02:XXXX:XXXX::/48 pltime=172800, vltime=259200
Apr 29 15:54:07 sofie dhcp6c[18258]: add an address 2a02:XXXX:XXXX:0:7e5a:1cff:fe54:3300/64 on igb0
Apr 29 15:54:07 sofie dhcp6c[18258]: add an address 2a02:XXXX:XXXX:2:7e5a:1cff:fe54:3303/64 on lagg0
Apr 29 15:54:07 sofie dhcp6c[18258]: add an address 2a02:XXXX:XXXX:20:7e5a:1cff:fe54:3303/64 on lagg0.20
Apr 29 15:54:07 sofie dhcp6c[18258]: status code for PD-0: success
Apr 29 15:54:07 sofie dhcp6c[18258]: executes /var/etc/dhcp6c_opt6_script.sh
Apr 29 15:54:07 sofie dhcp6c[58580]: dhcp6c RELEASE, REQUEST or EXIT on pppoe0 running rc.newwanipv6
Apr 29 15:54:07 sofie dhcp6c[18258]: script "/var/etc/dhcp6c_opt6_script.sh" terminated
Apr 29 15:54:07 sofie dhcp6c[18258]: removing an event on pppoe0, state=REQUEST
Apr 29 15:54:07 sofie dhcp6c[18258]: removing server (ID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd)
Apr 29 15:54:07 sofie dhcp6c[18258]: got an expected reply, sleeping.