Local ISP weird behaviour w/ IPv6 via DHCP6

bombadil · Jun 15, 2024, 1:47 AM

Hi all,
I recently switched to a regional ISP (LWLcom) that offers DSL dial-up via PPPoE and DHCP at the same time. Previously I had always used PPPoE as usual with DSL (which also works fine now) but I figured I'd try the DHCP connection for a MTU of 1500. IPv4 works fine, only IPv6 is meh.
I get a /60 subnet from the ISP, which pfSense requests normally via DHCP and is answered by the ISP with a 600s leasetime.

300 seconds later (as it is supposed to be?) pfSense tries to renew the lease, but this fails because the ISP router responds with a NoPrefixAvail. By trying to renew the lease, the provider router however deactivates the routing of the prefix to my line, since no prefix was assigned or renewed by their DHCP server. pfSense then continues to try to renew the prefix until it expires entirely and starts with a new, empty, solicit. Then I receive my prefix again for 600 seconds and the cycle starts all over again.

This is probably a completely flawed IPv6 configuration from my provider, but if I hook up an old FritzBox modem/router combination via DHCP for testing purposes, IPv6 runs continuously on the connection without any problems.

Maybe someone has already experienced something similar and has some tips for me.

pcap file from the screenshot pfsense-wan-dhcp-filtered.pcapng

Thanks!

YoLo88 · Jul 15, 2024, 10:52 AM

@bombadil I might be troubleshooting a very similar issue? I started out on reddit - https://www.reddit.com/r/PFSENSE/comments/1duuc6o/ipv6_troubles_unstable_pppoe_ipv6_address_via/. My IPv6 connection drops after 10 minutes and I'm trying to figure out why. Also moved from a Fritzbox that had no problem keeping it up over IPv6.

I was digging up old bugs like https://redmine.pfsense.org/issues/3484 looking for clues.

I have a pretty basic set up except for the fact that I'm not doing any prefix delegation and trying to get it to run over a single static /128 address and IPv6 NAT. It seems to work fine for 10 minutes and then the WAN connection will die and not recover. If I bounce my WAN interface, it comes straight back and works for another 10 minutes.

I'll post some more debug/logs tomorrow.

YoLo88 · Jul 16, 2024, 5:41 AM

This is a standard set of System logs for just after I issue the reconnect WAN via the WebUI:

Jul 16 17:26:16	ppp	77449	caught fatal signal TERM
Jul 16 17:26:16	ppp	77449	[wan] IFACE: Close event
Jul 16 17:26:16	ppp	77449	[wan] IPCP: Close event
Jul 16 17:26:16	ppp	77449	[wan] IPCP: state change Opened --> Closing
Jul 16 17:26:16	ppp	77449	[wan] IPCP: SendTerminateReq #4
Jul 16 17:26:16	ppp	77449	[wan] IPCP: LayerDown
Jul 16 17:26:16	check_reload_status	439	Rewriting resolv.conf
Jul 16 17:26:16	ppp	77449	[wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
Jul 16 17:26:16	ppp	77449	[wan] IPV6CP: Close event
Jul 16 17:26:16	ppp	77449	[wan] IPV6CP: state change Opened --> Closing
Jul 16 17:26:16	ppp	77449	[wan] IPV6CP: SendTerminateReq #2
Jul 16 17:26:16	ppp	77449	[wan] IPV6CP: LayerDown
Jul 16 17:26:18	check_reload_status	439	Rewriting resolv.conf
Jul 16 17:26:18	ppp	77449	[wan] IFACE: Down event
Jul 16 17:26:18	ppp	77449	[wan] IFACE: Rename interface pppoe0 to pppoe0
Jul 16 17:26:18	ppp	77449	[wan] IFACE: Set description "WAN"
Jul 16 17:26:18	ppp	77449	[wan] IPCP: rec'd Terminate Ack #4 (Closing)
Jul 16 17:26:18	ppp	77449	[wan] IPCP: state change Closing --> Closed
Jul 16 17:26:18	ppp	77449	[wan] IPCP: LayerFinish
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: rec'd Terminate Request #179 (Opened)
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: state change Opened --> Stopping
Jul 16 17:26:18	ppp	77449	[wan_link0] Link: Leave bundle "wan"
Jul 16 17:26:18	ppp	77449	[wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Jul 16 17:26:18	ppp	77449	[wan] IPCP: Close event
Jul 16 17:26:18	ppp	77449	[wan] IPV6CP: Close event
Jul 16 17:26:18	ppp	77449	[wan] IPCP: Down event
Jul 16 17:26:18	ppp	77449	[wan] IPCP: state change Closed --> Initial
Jul 16 17:26:18	ppp	77449	[wan] IPV6CP: Down event
Jul 16 17:26:18	ppp	77449	[wan] IPV6CP: LayerFinish
Jul 16 17:26:18	ppp	77449	[wan] Bundle: No NCPs left. Closing links...
Jul 16 17:26:18	ppp	77449	[wan] IPV6CP: state change Closing --> Initial
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: SendTerminateAck #3
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: LayerDown
Jul 16 17:26:18	ppp	77449	[wan] rec'd unexpected protocol IP
Jul 16 17:26:18	ppp	77449	[wan_link0] PPPoE: connection closed
Jul 16 17:26:18	ppp	77449	[wan_link0] Link: DOWN event
Jul 16 17:26:18	ppp	77449	[wan_link0] Link: giving up after 0 reconnection attempts
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: Close event
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: state change Stopping --> Closing
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: Down event
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: LayerFinish
Jul 16 17:26:18	ppp	77449	[wan_link0] LCP: state change Closing --> Initial
Jul 16 17:26:20	ppp	77449	[wan] Bundle: Shutdown
Jul 16 17:26:20	ppp	77449	[wan_link0] Link: Shutdown
Jul 16 17:26:20	ppp	77449	process 77449 terminated
Jul 16 17:26:20	php-fpm	399	/status_interfaces.php: Resyncing OpenVPN instances for interface WAN.
Jul 16 17:26:20	check_reload_status	439	Reloading filter
Jul 16 17:26:20	check_reload_status	439	Starting packages
Jul 16 17:26:21	php-fpm	398	/rc.start_packages: Restarting/Starting all packages.
Jul 16 17:26:21	SnortStartup	53003	Snort START for WAN(pppoe0)...
Jul 16 17:26:21	php-fpm	398	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes
Jul 16 17:26:21	check_reload_status	439	Syncing firewall
Jul 16 17:26:21	snort	58237	FATAL ERROR: Can't start DAQ (-1) - No such device exists!
Jul 16 17:26:22	php-fpm	398	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Firewall rules
Jul 16 17:26:22	check_reload_status	439	Syncing firewall
Jul 16 17:26:22	ppp	76000	Multi-link PPP daemon for FreeBSD
Jul 16 17:26:22	ppp	76000	process 76000 started, version 5.9
Jul 16 17:26:22	ppp	76000	web: web is not running
Jul 16 17:26:22	ppp	76000	[wan] Bundle: Interface ng0 created
Jul 16 17:26:22	ppp	76000	[wan_link0] Link: OPEN event
Jul 16 17:26:22	kernel		ng0: changing name to 'pppoe0'
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: Open event
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: state change Initial --> Starting
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: LayerStart
Jul 16 17:26:22	ppp	76000	[wan_link0] PPPoE: Connecting to ''
Jul 16 17:26:22	ppp	76000	PPPoE: rec'd ACNAME "wnjv-bng1"
Jul 16 17:26:22	ppp	76000	[wan_link0] PPPoE: connection successful
Jul 16 17:26:22	ppp	76000	[wan_link0] Link: UP event
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: Up event
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: state change Starting --> Req-Sent
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: SendConfigReq #1
Jul 16 17:26:22	ppp	76000	[wan_link0] PROTOCOMP
Jul 16 17:26:22	ppp	76000	[wan_link0] MRU 1492
Jul 16 17:26:22	ppp	76000	[wan_link0] MAGICNUM 0x03916120
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: rec'd Configure Request #156 (Req-Sent)
Jul 16 17:26:22	ppp	76000	[wan_link0] MRU 1500
Jul 16 17:26:22	ppp	76000	[wan_link0] AUTHPROTO PAP
Jul 16 17:26:22	ppp	76000	[wan_link0] MAGICNUM 0x5b234ccd
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: SendConfigAck #156
Jul 16 17:26:22	ppp	76000	[wan_link0] MRU 1500
Jul 16 17:26:22	ppp	76000	[wan_link0] AUTHPROTO PAP
Jul 16 17:26:22	ppp	76000	[wan_link0] MAGICNUM 0x5b234ccd
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: state change Req-Sent --> Ack-Sent
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
Jul 16 17:26:22	ppp	76000	[wan_link0] PROTOCOMP
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: SendConfigReq #2
Jul 16 17:26:22	ppp	76000	[wan_link0] MRU 1492
Jul 16 17:26:22	ppp	76000	[wan_link0] MAGICNUM 0x03916120
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
Jul 16 17:26:22	ppp	76000	[wan_link0] MRU 1492
Jul 16 17:26:22	ppp	76000	[wan_link0] MAGICNUM 0x03916120
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: state change Ack-Sent --> Opened
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: auth: peer wants PAP, I want nothing
Jul 16 17:26:22	ppp	76000	[wan_link0] PAP: using authname "paulwedde@snap.net.nz"
Jul 16 17:26:22	ppp	76000	[wan_link0] PAP: sending REQUEST #1 len: 39
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: LayerUp
Jul 16 17:26:22	ppp	76000	[wan_link0] PAP: rec'd ACK #1 len: 13
Jul 16 17:26:22	ppp	76000	[wan_link0] MESG: Login ok
Jul 16 17:26:22	ppp	76000	[wan_link0] LCP: authorization successful
Jul 16 17:26:22	ppp	76000	[wan_link0] Link: Matched action 'bundle "wan" ""'
Jul 16 17:26:22	ppp	76000	[wan_link0] Link: Join bundle "wan"
Jul 16 17:26:22	ppp	76000	[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Jul 16 17:26:22	ppp	76000	[wan] IPCP: Open event
Jul 16 17:26:22	ppp	76000	[wan] IPCP: state change Initial --> Starting
Jul 16 17:26:22	ppp	76000	[wan] IPCP: LayerStart
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: Open event
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: state change Initial --> Starting
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: LayerStart
Jul 16 17:26:22	ppp	76000	[wan] IPCP: Up event
Jul 16 17:26:22	ppp	76000	[wan] IPCP: state change Starting --> Req-Sent
Jul 16 17:26:22	ppp	76000	[wan] IPCP: SendConfigReq #1
Jul 16 17:26:22	ppp	76000	[wan] IPADDR 0.0.0.0
Jul 16 17:26:22	ppp	76000	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: Up event
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: state change Starting --> Req-Sent
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: SendConfigReq #1
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: rec'd Configure Request #130 (Req-Sent)
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: SendConfigAck #130
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: state change Req-Sent --> Ack-Sent
Jul 16 17:26:22	ppp	76000	[wan] IPCP: rec'd Configure Request #96 (Req-Sent)
Jul 16 17:26:22	ppp	76000	[wan] IPADDR [x.x.x.x]
Jul 16 17:26:22	ppp	76000	[wan] [x.x.x.x] is OK
Jul 16 17:26:22	ppp	76000	[wan] IPCP: SendConfigAck #96
Jul 16 17:26:22	ppp	76000	[wan] IPADDR [x.x.x.x]
Jul 16 17:26:22	ppp	76000	[wan] IPCP: state change Req-Sent --> Ack-Sent
Jul 16 17:26:22	ppp	76000	[wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
Jul 16 17:26:22	ppp	76000	[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jul 16 17:26:22	ppp	76000	[wan] IPCP: SendConfigReq #2
Jul 16 17:26:22	ppp	76000	[wan] IPADDR 0.0.0.0
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: rec'd Configure Ack #1 (Ack-Sent)
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: state change Ack-Sent --> Opened
Jul 16 17:26:22	ppp	76000	[wan] IPV6CP: LayerUp
Jul 16 17:26:22	ppp	76000	[wan] [xxxx:xxxx:xxxx:xxxx:] -> [xxxx:xxxx:xxxx:xxxx:]
Jul 16 17:26:22	check_reload_status	439	Reloading filter
Jul 16 17:26:22	tail_pfb	78837	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:22	php_pfb	79609	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:22	php-fpm	398	[pfBlockerNG] Restarting firewall filter daemon
Jul 16 17:26:22	tail_pfb	84193	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:22	tail_pfb	84879	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:22	php_pfb	85640	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:22	php_pfb	86159	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:22	tail_pfb	90527	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:26:22	tail_pfb	91925	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:26:22	php	77929	/usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
Jul 16 17:26:22	php	77929	/usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode
Jul 16 17:26:22	php	77929	/usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
Jul 16 17:26:22	php_pfb	91638	[pfBlockerNG] filterlog daemon started
Jul 16 17:26:22	php_pfb	92180	[pfBlockerNG] filterlog daemon started
Jul 16 17:26:24	check_reload_status	439	rc.newwanipv6 starting pppoe0
Jul 16 17:26:24	ppp	76000	[wan] IFACE: Up event
Jul 16 17:26:24	ppp	76000	[wan] IFACE: Rename interface ng0 to pppoe0
Jul 16 17:26:24	ppp	76000	[wan] IFACE: Add description "WAN"
Jul 16 17:26:24	ppp	76000	[wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Jul 16 17:26:24	ppp	76000	[wan] IPADDR [x.x.x.x]
Jul 16 17:26:24	ppp	76000	[wan] [x.x.x.x] is OK
Jul 16 17:26:24	ppp	76000	[wan] IPCP: SendConfigReq #3
Jul 16 17:26:24	ppp	76000	[wan] IPADDR [x.x.x.x]
Jul 16 17:26:24	ppp	76000	[wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Jul 16 17:26:24	ppp	76000	[wan] IPADDR [x.x.x.x]
Jul 16 17:26:24	ppp	76000	[wan] IPCP: state change Ack-Sent --> Opened
Jul 16 17:26:24	ppp	76000	[wan] IPCP: LayerUp
Jul 16 17:26:24	ppp	76000	[wan] [x.x.x.x] -> [x.x.x.x]
Jul 16 17:26:24	check_reload_status	439	rc.newwanip starting pppoe0
Jul 16 17:26:25	php-fpm	38529	/status_interfaces.php: calling interface_dhcpv6_configure.
Jul 16 17:26:25	php-fpm	399	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Jul 16 17:26:25	php-fpm	399	/rc.newwanipv6: rc.newwanipv6: on (IP address: [xxxx:xxxx:xxxx:xxxx::xxxx]) (interface: wan) (real interface: pppoe0).
Jul 16 17:26:25	rtsold	27073	Received RA specifying route [fe80::xxxx:xxxx:xxxx] for interface wan(pppoe0)
Jul 16 17:26:25	php-fpm	45454	/rc.newwanip: rc.newwanip: Info: starting on pppoe0.
Jul 16 17:26:25	php-fpm	45454	/rc.newwanip: rc.newwanip: on (IP address: [x.x.x.x]) (interface: WAN[wan]) (real interface: pppoe0).
Jul 16 17:26:26	php-fpm	38529	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Jul 16 17:26:26	php-fpm	38529	/rc.newwanipv6: rc.newwanipv6: on (IP address: [xxxx:xxxx:xxxx:xxxx::xxxx]) (interface: wan) (real interface: pppoe0).
Jul 16 17:26:27	php-fpm	45454	/rc.newwanip: The command '/usr/local/bin/dpinger -S -r 0 -i WAN_DHCP6 -B [fe80::xxxx:xxxx:xxxx]%pppoe0 -p /var/run/dpinger_WAN_DHCP6~[fe80::xxxx:xxxx:xxxx%pppoe0~fe80::xxxx:xxxx:xxxx]%pppoe0.pid -u /var/run/dpinger_WAN_DHCP6~[fe80::xxxx:xxxx:xxxx%pppoe0~fe80::xxxx:xxxx:xxxx]%pppoe0.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 [fe80::xxxx:xxxx:xxxx]%pppoe0 >/dev/null' returned exit code '1', the output was ''
Jul 16 17:26:27	php-fpm	45454	/rc.newwanip: Error starting gateway monitor for WAN_DHCP6
Jul 16 17:26:27	php-fpm	399	/rc.newwanipv6: Default gateway setting Interface WAN_PPPOE Gateway as default.
Jul 16 17:26:27	php-fpm	38529	/rc.newwanipv6: Default gateway setting Interface WAN_PPPOE Gateway as default.
Jul 16 17:26:27	check_reload_status	439	Reloading filter
Jul 16 17:26:27	check_reload_status	439	Reloading filter
Jul 16 17:26:27	php-fpm	399	/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
Jul 16 17:26:27	php-fpm	38529	/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
Jul 16 17:26:27	php-fpm	399	/rc.newwanipv6: Creating rrd update script
Jul 16 17:26:27	php-fpm	38529	/rc.newwanipv6: Creating rrd update script
Jul 16 17:26:27	php-fpm	399	/rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - -> [xxxx:xxxx:xxxx:xxxx::xxxx] - Restarting packages.
Jul 16 17:26:27	check_reload_status	439	Starting packages
Jul 16 17:26:27	php-fpm	38529	/rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - -> [xxxx:xxxx:xxxx:xxxx::xxxx] - Restarting packages.
Jul 16 17:26:27	check_reload_status	439	Starting packages
Jul 16 17:26:27	php-fpm	45454	/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Jul 16 17:26:27	php-fpm	45454	/rc.newwanip: Creating rrd update script
Jul 16 17:26:28	php-fpm	399	/rc.start_packages: Restarting/Starting all packages.
Jul 16 17:26:28	php-fpm	13863	/rc.start_packages: Restarting/Starting all packages.
Jul 16 17:26:28	php-fpm	399	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes
Jul 16 17:26:28	check_reload_status	439	Syncing firewall
Jul 16 17:26:28	php-fpm	13863	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes
Jul 16 17:26:28	check_reload_status	439	Syncing firewall
Jul 16 17:26:29	php-fpm	399	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Firewall rules
Jul 16 17:26:29	php-fpm	13863	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving Firewall rules
Jul 16 17:26:29	check_reload_status	439	Syncing firewall
Jul 16 17:26:29	check_reload_status	439	Reloading filter
Jul 16 17:26:29	check_reload_status	439	Reloading filter
Jul 16 17:26:29	tail_pfb	51455	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:29	tail_pfb	51676	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:29	php_pfb	52689	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:29	php_pfb	52937	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:29	php-fpm	399	[pfBlockerNG] Restarting firewall filter daemon
Jul 16 17:26:29	php-fpm	13863	[pfBlockerNG] Restarting firewall filter daemon
Jul 16 17:26:29	tail_pfb	62040	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:29	tail_pfb	62171	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:29	tail_pfb	63585	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:29	tail_pfb	64016	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:29	php_pfb	65124	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:29	php_pfb	65497	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:29	php_pfb	65517	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:29	php_pfb	66642	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:29	tail_pfb	73685	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:26:29	tail_pfb	74107	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:26:29	tail_pfb	74628	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:26:29	tail_pfb	75647	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:26:30	php-fpm	45454	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - [x.x.x.x] -> [x.x.x.x] 0 - Restarting packages.
Jul 16 17:26:30	check_reload_status	439	Starting packages
Jul 16 17:26:30	php_pfb	75413	[pfBlockerNG] filterlog daemon started
Jul 16 17:26:30	php_pfb	76255	[pfBlockerNG] filterlog daemon started
Jul 16 17:26:30	php_pfb	78811	[pfBlockerNG] filterlog daemon started
Jul 16 17:26:30	php_pfb	76540	[pfBlockerNG] filterlog daemon started
Jul 16 17:26:31	php-fpm	13863	/rc.start_packages: Restarting/Starting all packages.
Jul 16 17:26:31	SnortStartup	12698	Snort START for WAN(pppoe0)...
Jul 16 17:26:31	php-fpm	13863	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes
Jul 16 17:26:31	check_reload_status	439	Syncing firewall
Jul 16 17:26:31	kernel		pppoe0: promiscuous mode enabled
Jul 16 17:26:31	tail_pfb	59967	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:26:31	php_pfb	60873	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:26:31	tail_pfb	64326	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:26:31	php_pfb	64519	[pfBlockerNG] filterlog daemon started

And the equivalent DHCPv6 Logs:

Jul 16 17:26:17	dhcp6c	79236	exit without release
Jul 16 17:26:17	dhcp6c	79236	removing an event on pppoe0, state=SOLICIT
Jul 16 17:26:17	dhcp6c	79236	removing an event on pppoe0, state=SOLICIT
Jul 16 17:26:17	dhcp6c	79236	executes /var/etc/dhcp6c_wan_dhcp6withoutra_script.sh
Jul 16 17:26:17	dhcp6c	73451	lstat failed: No such file or directory
Jul 16 17:26:17	dhcp6c	73451	script "/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh" cannot be executed safely
Jul 16 17:26:17	dhcp6c	79236	script "/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh" terminated
Jul 16 17:26:17	dhcp6c	79236	exiting
Jul 16 17:26:22	dhcp6c	93223	extracted an existing DUID from /var/db/dhcp6c_duid: xxxx
Jul 16 17:26:22	dhcp6c	93223	failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Jul 16 17:26:22	dhcp6c	93223	failed initialize control message authentication
Jul 16 17:26:22	dhcp6c	93223	skip opening control port
Jul 16 17:26:22	dhcp6c	93223	<3>[interface] (9)
Jul 16 17:26:22	dhcp6c	93223	<5>[pppoe0] (6)
Jul 16 17:26:22	dhcp6c	93223	<3>begin of closure [{] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>[send] (4)
Jul 16 17:26:22	dhcp6c	93223	<3>[ia-na] (5)
Jul 16 17:26:22	dhcp6c	93223	<3>[0] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>comment [# request stateful address] (26)
Jul 16 17:26:22	dhcp6c	93223	<3>[send] (4)
Jul 16 17:26:22	dhcp6c	93223	<3>[ia-pd] (5)
Jul 16 17:26:22	dhcp6c	93223	<3>[0] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>comment [# request prefix delegation] (27)
Jul 16 17:26:22	dhcp6c	93223	<3>[request] (7)
Jul 16 17:26:22	dhcp6c	93223	<3>[domain-name-servers] (19)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>[request] (7)
Jul 16 17:26:22	dhcp6c	93223	<3>[domain-name] (11)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>[script] (6)
Jul 16 17:26:22	dhcp6c	93223	<3>["/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh"] (46)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>comment [# we'd like nameservers and RTSOLD to do all the work] (53)
Jul 16 17:26:22	dhcp6c	93223	<3>end of closure [}] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>[id-assoc] (8)
Jul 16 17:26:22	dhcp6c	93223	<13>[na] (2)
Jul 16 17:26:22	dhcp6c	93223	<13>[0] (1)
Jul 16 17:26:22	dhcp6c	93223	<13>begin of closure [{] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>end of closure [}] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>[id-assoc] (8)
Jul 16 17:26:22	dhcp6c	93223	<13>[pd] (2)
Jul 16 17:26:22	dhcp6c	93223	<13>[0] (1)
Jul 16 17:26:22	dhcp6c	93223	<13>begin of closure [{] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>[prefix] (6)
Jul 16 17:26:22	dhcp6c	93223	<3>[::] (2)
Jul 16 17:26:22	dhcp6c	93223	<3>[/] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>[64] (2)
Jul 16 17:26:22	dhcp6c	93223	<3>[infinity] (8)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>end of closure [}] (1)
Jul 16 17:26:22	dhcp6c	93223	<3>end of sentence [;] (1)
Jul 16 17:26:22	dhcp6c	93223	called
Jul 16 17:26:22	dhcp6c	93223	called
Jul 16 17:26:22	dhcp6c	93453	reset a timer on pppoe0, state=INIT, timeo=0, retrans=891
Jul 16 17:26:23	dhcp6c	93453	Sending Solicit
Jul 16 17:26:23	dhcp6c	93453	a new XID (a581a) is generated
Jul 16 17:26:23	dhcp6c	93453	set client ID (len 14)
Jul 16 17:26:23	dhcp6c	93453	set identity association
Jul 16 17:26:23	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:26:23	dhcp6c	93453	set option request (len 4)
Jul 16 17:26:23	dhcp6c	93453	set IA_PD prefix
Jul 16 17:26:23	dhcp6c	93453	set IA_PD
Jul 16 17:26:23	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:26:23	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1091
Jul 16 17:26:24	dhcp6c	93453	Sending Solicit
Jul 16 17:26:24	dhcp6c	93453	set client ID (len 14)
Jul 16 17:26:24	dhcp6c	93453	set identity association
Jul 16 17:26:24	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:26:24	dhcp6c	93453	set option request (len 4)
Jul 16 17:26:24	dhcp6c	93453	set IA_PD prefix
Jul 16 17:26:24	dhcp6c	93453	set IA_PD
Jul 16 17:26:24	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:26:24	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=1, retrans=2083
Jul 16 17:26:24	dhcp6c	93453	receive advertise from [fe80::xxxx:xxxx:xxxx]%pppoe0 on pppoe0
Jul 16 17:26:24	dhcp6c	93453	get DHCP option server ID, len 10
Jul 16 17:26:24	dhcp6c	93453	DUID: xxx
Jul 16 17:26:24	dhcp6c	93453	get DHCP option client ID, len 14
Jul 16 17:26:24	dhcp6c	93453	DUID: xxx
Jul 16 17:26:24	dhcp6c	93453	get DHCP option identity association, len 40
Jul 16 17:26:24	dhcp6c	93453	IA_NA: ID=0, T1=300, T2=480
Jul 16 17:26:24	dhcp6c	93453	get DHCP option IA address, len 24
Jul 16 17:26:24	dhcp6c	93453	IA_NA address: [xxxx:xxxx:xxxx:xxxx::xxxx] pltime=600 vltime=600
Jul 16 17:26:24	dhcp6c	93453	get DHCP option IA_PD, len 41
Jul 16 17:26:24	dhcp6c	93453	IA_PD: ID=0, T1=300, T2=480
Jul 16 17:26:24	dhcp6c	93453	get DHCP option IA_PD prefix, len 25
Jul 16 17:26:24	dhcp6c	93453	IA_PD prefix: [xxxx:xxxx:xxxx:xxxx::]/64 pltime=600 vltime=17984653545969812056
Jul 16 17:26:24	dhcp6c	93453	server ID: xxx, pref=-1
Jul 16 17:26:24	dhcp6c	93453	reset timer for pppoe0 to 0.997789
Jul 16 17:26:25	dhcp6c	93453	picked a server (ID: xxx)
Jul 16 17:26:25	dhcp6c	93453	Sending Request
Jul 16 17:26:25	dhcp6c	93453	a new XID (872565) is generated
Jul 16 17:26:25	dhcp6c	93453	set client ID (len 14)
Jul 16 17:26:25	dhcp6c	93453	set server ID (len 10)
Jul 16 17:26:25	dhcp6c	93453	set IA address
Jul 16 17:26:25	dhcp6c	93453	set identity association
Jul 16 17:26:25	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:26:25	dhcp6c	93453	set option request (len 4)
Jul 16 17:26:25	dhcp6c	93453	set IA_PD prefix
Jul 16 17:26:25	dhcp6c	93453	set IA_PD
Jul 16 17:26:25	dhcp6c	93453	send request to ff02::1:2%pppoe0
Jul 16 17:26:25	dhcp6c	93453	reset a timer on pppoe0, state=REQUEST, timeo=0, retrans=911
Jul 16 17:26:25	dhcp6c	93453	receive reply from [fe80::xxxx:xxxx:xxxx]%pppoe0 on pppoe0
Jul 16 17:26:25	dhcp6c	93453	get DHCP option server ID, len 10
Jul 16 17:26:25	dhcp6c	93453	DUID: xxx
Jul 16 17:26:25	dhcp6c	93453	get DHCP option client ID, len 14
Jul 16 17:26:25	dhcp6c	93453	DUID: xxx
Jul 16 17:26:25	dhcp6c	93453	get DHCP option identity association, len 40
Jul 16 17:26:25	dhcp6c	93453	IA_NA: ID=0, T1=300, T2=480
Jul 16 17:26:25	dhcp6c	93453	get DHCP option IA address, len 24
Jul 16 17:26:25	dhcp6c	93453	IA_NA address: [xxxx:xxxx:xxxx:xxxx::xxxx] pltime=600 vltime=600
Jul 16 17:26:25	dhcp6c	93453	get DHCP option IA_PD, len 41
Jul 16 17:26:25	dhcp6c	93453	IA_PD: ID=0, T1=300, T2=480
Jul 16 17:26:25	dhcp6c	93453	get DHCP option IA_PD prefix, len 25
Jul 16 17:26:25	dhcp6c	93453	IA_PD prefix: [xxxx:xxxx:xxxx:xxxx::]/64 pltime=600 vltime=17984653545969812056
Jul 16 17:26:25	dhcp6c	93453	dhcp6c Received REQUEST
Jul 16 17:26:25	dhcp6c	93453	make an IA: PD-0
Jul 16 17:26:25	dhcp6c	93453	create a prefix [xxxx:xxxx:xxxx:xxxx::]/64 pltime=600, vltime=600
Jul 16 17:26:25	dhcp6c	93453	make an IA: NA-0
Jul 16 17:26:25	dhcp6c	93453	create an address [xxxx:xxxx:xxxx:xxxx::xxxx] pltime=600, vltime=34359738968
Jul 16 17:26:25	dhcp6c	93453	add an address [xxxx:xxxx:xxxx:xxxx::xxxx]/128 on pppoe0
Jul 16 17:26:25	dhcp6c	93453	executes /var/etc/dhcp6c_wan_dhcp6withoutra_script.sh
Jul 16 17:26:25	dhcp6c	24167	dhcp6c REQUEST on pppoe0 - running rtsold
Jul 16 17:26:25	dhcp6c	93453	script "/var/etc/dhcp6c_wan_dhcp6withoutra_script.sh" terminated
Jul 16 17:26:25	dhcp6c	93453	removing an event on pppoe0, state=REQUEST
Jul 16 17:26:25	dhcp6c	93453	removing server (ID: xxx)
Jul 16 17:26:25	dhcp6c	93453	got an expected reply, sleeping.

YoLo88 · Jul 16, 2024, 6:38 AM

And here are the logs for 10 minutes later when the IPv6 is dropped and the Interface never recovers -

System Logs

Jul 16 17:36:41	rc.gateway_alarm	99403	>>> Gateway alarm: WAN_DHCP6 (Addr:[fe80::xxx:xxxx:xxxx:xxxx]%pppoe0 Alarm:1 RTT:1.447ms RTTsd:.421ms Loss:21%)
Jul 16 17:36:41	check_reload_status	439	updating dyndns WAN_DHCP6
Jul 16 17:36:41	check_reload_status	439	Restarting IPsec tunnels
Jul 16 17:36:41	check_reload_status	439	Restarting OpenVPN tunnels/interfaces
Jul 16 17:36:41	check_reload_status	439	Reloading filter
Jul 16 17:38:33	rtsold	98738	Received RA specifying route [fe80::xxx:xxxx:xxxx:xxxx] for interface wan(pppoe0)
Jul 16 17:38:34	php-fpm	45454	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Jul 16 17:38:34	php-fpm	45454	/rc.newwanipv6: rc.newwanipv6: on (IP address: [NEW IPv6 Address]) (interface: wan) (real interface: pppoe0).
Jul 16 17:38:35	check_reload_status	439	Reloading filter
Jul 16 17:38:35	php-fpm	45454	/rc.newwanipv6: The command '/sbin/ifconfig pppoe0 inet6 [OLD IPv6 Address] delete' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address'
Jul 16 17:38:35	php-fpm	45454	/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
Jul 16 17:38:35	php-fpm	45454	/rc.newwanipv6: Creating rrd update script
Jul 16 17:38:35	php-fpm	45454	/rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - [OLD IPv6 Address] -> [NEW IPv6 Address] - Restarting packages.
Jul 16 17:38:35	check_reload_status	439	Starting packages
Jul 16 17:38:35	check_reload_status	439	Reloading filter
Jul 16 17:38:36	php-fpm	399	/rc.start_packages: Restarting/Starting all packages.
Jul 16 17:38:36	php-fpm	399	/rc.start_packages: Configuration Change: (system): pfBlockerNG: saving DNSBL changes
Jul 16 17:38:36	check_reload_status	439	Syncing firewall
Jul 16 17:38:37	tail_pfb	73078	[pfBlockerNG] Firewall Filter Service stopped
Jul 16 17:38:37	php_pfb	74496	[pfBlockerNG] filterlog daemon stopped
Jul 16 17:38:37	tail_pfb	82097	[pfBlockerNG] Firewall Filter Service started
Jul 16 17:38:37	php_pfb	82636	[pfBlockerNG] filterlog daemon started
Jul 16 17:38:46	rtsold	54756	Received RA specifying route [fe80::xxx:xxxx:xxxx:xxxx] for interface wan(pppoe0)
Jul 16 17:38:47	php-fpm	38529	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0.
Jul 16 17:38:47	php-fpm	38529	/rc.newwanipv6: rc.newwanipv6: on (IP address: [NEW IPv6 Address]) (interface: wan) (real interface: pppoe0).
Jul 16 17:38:48	check_reload_status	439	Reloading filter
Jul 16 17:38:48	php-fpm	38529	/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
Jul 16 17:38:48	check_reload_status	439	Reloading filter

DHCP6c Debug Logs:

Jul 16 17:31:25	dhcp6c	93453	IA timeout for NA-0, state=ACTIVE
Jul 16 17:31:25	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=0, retrans=10256
Jul 16 17:31:25	dhcp6c	93453	Sending Renew
Jul 16 17:31:25	dhcp6c	93453	a new XID (9e65a3) is generated
Jul 16 17:31:25	dhcp6c	93453	set client ID (len 14)
Jul 16 17:31:25	dhcp6c	93453	set server ID (len 10)
Jul 16 17:31:25	dhcp6c	93453	set IA address
Jul 16 17:31:25	dhcp6c	93453	set identity association
Jul 16 17:31:25	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:31:25	dhcp6c	93453	set option request (len 4)
Jul 16 17:31:25	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:31:25	dhcp6c	93453	IA timeout for PD-0, state=ACTIVE
Jul 16 17:31:25	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=0, retrans=10244
Jul 16 17:31:25	dhcp6c	93453	Sending Renew
Jul 16 17:31:25	dhcp6c	93453	a new XID (4cb9b4) is generated
Jul 16 17:31:25	dhcp6c	93453	set client ID (len 14)
Jul 16 17:31:25	dhcp6c	93453	set server ID (len 10)
Jul 16 17:31:25	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:31:25	dhcp6c	93453	set option request (len 4)
Jul 16 17:31:25	dhcp6c	93453	set IA_PD prefix
Jul 16 17:31:25	dhcp6c	93453	set IA_PD
Jul 16 17:31:25	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:31:35	dhcp6c	93453	Sending Renew
Jul 16 17:31:35	dhcp6c	93453	set client ID (len 14)
Jul 16 17:31:35	dhcp6c	93453	set server ID (len 10)
Jul 16 17:31:35	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:31:35	dhcp6c	93453	set option request (len 4)
Jul 16 17:31:35	dhcp6c	93453	set IA_PD prefix
Jul 16 17:31:35	dhcp6c	93453	set IA_PD
Jul 16 17:31:35	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:31:35	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=1, retrans=20034
Jul 16 17:31:35	dhcp6c	93453	Sending Renew
Jul 16 17:31:35	dhcp6c	93453	set client ID (len 14)
Jul 16 17:31:35	dhcp6c	93453	set server ID (len 10)
Jul 16 17:31:35	dhcp6c	93453	set IA address
Jul 16 17:31:35	dhcp6c	93453	set identity association
Jul 16 17:31:35	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:31:35	dhcp6c	93453	set option request (len 4)
Jul 16 17:31:35	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:31:35	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=1, retrans=20708
Jul 16 17:31:56	dhcp6c	93453	Sending Renew
Jul 16 17:31:56	dhcp6c	93453	set client ID (len 14)
Jul 16 17:31:56	dhcp6c	93453	set server ID (len 10)
Jul 16 17:31:56	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:31:56	dhcp6c	93453	set option request (len 4)
Jul 16 17:31:56	dhcp6c	93453	set IA_PD prefix
Jul 16 17:31:56	dhcp6c	93453	set IA_PD
Jul 16 17:31:56	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:31:56	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=2, retrans=39893
Jul 16 17:31:56	dhcp6c	93453	Sending Renew
Jul 16 17:31:56	dhcp6c	93453	set client ID (len 14)
Jul 16 17:31:56	dhcp6c	93453	set server ID (len 10)
Jul 16 17:31:56	dhcp6c	93453	set IA address
Jul 16 17:31:56	dhcp6c	93453	set identity association
Jul 16 17:31:56	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:31:56	dhcp6c	93453	set option request (len 4)
Jul 16 17:31:56	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:31:56	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=2, retrans=40140
Jul 16 17:32:35	dhcp6c	93453	Sending Renew
Jul 16 17:32:35	dhcp6c	93453	set client ID (len 14)
Jul 16 17:32:35	dhcp6c	93453	set server ID (len 10)
Jul 16 17:32:35	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:32:35	dhcp6c	93453	set option request (len 4)
Jul 16 17:32:35	dhcp6c	93453	set IA_PD prefix
Jul 16 17:32:35	dhcp6c	93453	set IA_PD
Jul 16 17:32:35	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:32:35	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=3, retrans=80895
Jul 16 17:32:36	dhcp6c	93453	Sending Renew
Jul 16 17:32:36	dhcp6c	93453	set client ID (len 14)
Jul 16 17:32:36	dhcp6c	93453	set server ID (len 10)
Jul 16 17:32:36	dhcp6c	93453	set IA address
Jul 16 17:32:36	dhcp6c	93453	set identity association
Jul 16 17:32:36	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:32:36	dhcp6c	93453	set option request (len 4)
Jul 16 17:32:36	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:32:36	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=3, retrans=77269
Jul 16 17:33:54	dhcp6c	93453	Sending Renew
Jul 16 17:33:54	dhcp6c	93453	set client ID (len 14)
Jul 16 17:33:54	dhcp6c	93453	set server ID (len 10)
Jul 16 17:33:54	dhcp6c	93453	set IA address
Jul 16 17:33:54	dhcp6c	93453	set identity association
Jul 16 17:33:54	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:33:54	dhcp6c	93453	set option request (len 4)
Jul 16 17:33:54	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:33:54	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=4, retrans=155001
Jul 16 17:33:56	dhcp6c	93453	Sending Renew
Jul 16 17:33:56	dhcp6c	93453	set client ID (len 14)
Jul 16 17:33:56	dhcp6c	93453	set server ID (len 10)
Jul 16 17:33:56	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:33:56	dhcp6c	93453	set option request (len 4)
Jul 16 17:33:56	dhcp6c	93453	set IA_PD prefix
Jul 16 17:33:56	dhcp6c	93453	set IA_PD
Jul 16 17:33:56	dhcp6c	93453	send renew to ff02::1:2%pppoe0
Jul 16 17:33:56	dhcp6c	93453	reset a timer on pppoe0, state=RENEW, timeo=4, retrans=154040
Jul 16 17:34:25	dhcp6c	93453	IA timeout for NA-0, state=RENEW
Jul 16 17:34:25	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=0, retrans=9245
Jul 16 17:34:25	dhcp6c	93453	Sending Rebind
Jul 16 17:34:25	dhcp6c	93453	a new XID (4e5a83) is generated
Jul 16 17:34:25	dhcp6c	93453	set client ID (len 14)
Jul 16 17:34:25	dhcp6c	93453	set IA address
Jul 16 17:34:25	dhcp6c	93453	set identity association
Jul 16 17:34:25	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:34:25	dhcp6c	93453	set option request (len 4)
Jul 16 17:34:25	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:34:25	dhcp6c	93453	IA timeout for PD-0, state=RENEW
Jul 16 17:34:25	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=0, retrans=9832
Jul 16 17:34:25	dhcp6c	93453	Sending Rebind
Jul 16 17:34:25	dhcp6c	93453	a new XID (b44aee) is generated
Jul 16 17:34:25	dhcp6c	93453	set client ID (len 14)
Jul 16 17:34:25	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:34:25	dhcp6c	93453	set option request (len 4)
Jul 16 17:34:25	dhcp6c	93453	set IA_PD prefix
Jul 16 17:34:25	dhcp6c	93453	set IA_PD
Jul 16 17:34:25	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:34:34	dhcp6c	93453	Sending Rebind
Jul 16 17:34:34	dhcp6c	93453	set client ID (len 14)
Jul 16 17:34:34	dhcp6c	93453	set IA address
Jul 16 17:34:34	dhcp6c	93453	set identity association
Jul 16 17:34:34	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:34:34	dhcp6c	93453	set option request (len 4)
Jul 16 17:34:34	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:34:34	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=1, retrans=18333
Jul 16 17:34:35	dhcp6c	93453	Sending Rebind
Jul 16 17:34:35	dhcp6c	93453	set client ID (len 14)
Jul 16 17:34:35	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:34:35	dhcp6c	93453	set option request (len 4)
Jul 16 17:34:35	dhcp6c	93453	set IA_PD prefix
Jul 16 17:34:35	dhcp6c	93453	set IA_PD
Jul 16 17:34:35	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:34:35	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=1, retrans=18742
Jul 16 17:34:53	dhcp6c	93453	Sending Rebind
Jul 16 17:34:53	dhcp6c	93453	set client ID (len 14)
Jul 16 17:34:53	dhcp6c	93453	set IA address
Jul 16 17:34:53	dhcp6c	93453	set identity association
Jul 16 17:34:53	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:34:53	dhcp6c	93453	set option request (len 4)
Jul 16 17:34:53	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:34:53	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=2, retrans=36526
Jul 16 17:34:54	dhcp6c	93453	Sending Rebind
Jul 16 17:34:54	dhcp6c	93453	set client ID (len 14)
Jul 16 17:34:54	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:34:54	dhcp6c	93453	set option request (len 4)
Jul 16 17:34:54	dhcp6c	93453	set IA_PD prefix
Jul 16 17:34:54	dhcp6c	93453	set IA_PD
Jul 16 17:34:54	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:34:54	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=2, retrans=37305
Jul 16 17:35:29	dhcp6c	93453	Sending Rebind
Jul 16 17:35:29	dhcp6c	93453	set client ID (len 14)
Jul 16 17:35:29	dhcp6c	93453	set IA address
Jul 16 17:35:29	dhcp6c	93453	set identity association
Jul 16 17:35:29	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:35:29	dhcp6c	93453	set option request (len 4)
Jul 16 17:35:29	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:35:29	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=3, retrans=69545
Jul 16 17:35:31	dhcp6c	93453	Sending Rebind
Jul 16 17:35:31	dhcp6c	93453	set client ID (len 14)
Jul 16 17:35:31	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:35:31	dhcp6c	93453	set option request (len 4)
Jul 16 17:35:31	dhcp6c	93453	set IA_PD prefix
Jul 16 17:35:31	dhcp6c	93453	set IA_PD
Jul 16 17:35:31	dhcp6c	93453	send rebind to ff02::1:2%pppoe0
Jul 16 17:35:31	dhcp6c	93453	reset a timer on pppoe0, state=REBIND, timeo=3, retrans=77631

[From here is almost 10 minutes (9 minutes and 54s) from when the previous lease was acquired]
Jul 16 17:36:25	dhcp6c	93453	address timeout for [OLD IPv6 Address]
Jul 16 17:36:25	dhcp6c	93453	remove an address [OLD IPv6 Address]
Jul 16 17:36:25	dhcp6c	93453	remove an address [OLD IPv6 Address]/128 on pppoe0
Jul 16 17:36:25	dhcp6c	93453	IA NA-0 is invalidated
Jul 16 17:36:25	dhcp6c	93453	remove an IA: NA-0
Jul 16 17:36:25	dhcp6c	93453	reset a timer on pppoe0, state=INIT, timeo=0, retrans=288
Jul 16 17:36:25	dhcp6c	93453	prefix timeout for [IPv6 Delegated Prefix]::/64
Jul 16 17:36:25	dhcp6c	93453	remove a site prefix [IPv6 Delegated Prefix]::/64
Jul 16 17:36:25	dhcp6c	93453	IA PD-0 is invalidated
Jul 16 17:36:25	dhcp6c	93453	remove an IA: PD-0
Jul 16 17:36:25	dhcp6c	93453	reset a timer on pppoe0, state=INIT, timeo=0, retrans=843
Jul 16 17:36:26	dhcp6c	93453	Sending Solicit
Jul 16 17:36:26	dhcp6c	93453	a new XID (c66ca2) is generated
Jul 16 17:36:26	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:26	dhcp6c	93453	set identity association
Jul 16 17:36:26	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:26	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:26	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:26	dhcp6c	93453	set IA_PD
Jul 16 17:36:26	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:26	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1071
Jul 16 17:36:26	dhcp6c	93453	Sending Solicit
Jul 16 17:36:26	dhcp6c	93453	a new XID (318b1c) is generated
Jul 16 17:36:26	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:26	dhcp6c	93453	set identity association
Jul 16 17:36:26	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:26	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:26	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:26	dhcp6c	93453	set IA_PD
Jul 16 17:36:26	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:26	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1024
Jul 16 17:36:27	dhcp6c	93453	Sending Solicit
Jul 16 17:36:27	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:27	dhcp6c	93453	set identity association
Jul 16 17:36:27	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:27	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:27	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:27	dhcp6c	93453	set IA_PD
Jul 16 17:36:27	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:27	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=1, retrans=2222
Jul 16 17:36:27	dhcp6c	93453	Sending Solicit
Jul 16 17:36:27	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:27	dhcp6c	93453	set identity association
Jul 16 17:36:27	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:27	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:27	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:27	dhcp6c	93453	set IA_PD
Jul 16 17:36:27	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:27	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=1, retrans=1992
Jul 16 17:36:29	dhcp6c	93453	all information to be updated was canceled
Jul 16 17:36:29	dhcp6c	93453	removing an event on pppoe0, state=RENEW
Jul 16 17:36:29	dhcp6c	93453	Sending Solicit
Jul 16 17:36:29	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:29	dhcp6c	93453	set identity association
Jul 16 17:36:29	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:29	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:29	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:29	dhcp6c	93453	set IA_PD
Jul 16 17:36:29	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:29	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=2, retrans=4305
Jul 16 17:36:29	dhcp6c	93453	Sending Solicit
Jul 16 17:36:29	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:29	dhcp6c	93453	set identity association
Jul 16 17:36:29	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:29	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:29	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:29	dhcp6c	93453	set IA_PD
Jul 16 17:36:29	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:29	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=2, retrans=3810
Jul 16 17:36:30	dhcp6c	93453	all information to be updated was canceled
Jul 16 17:36:30	dhcp6c	93453	removing an event on pppoe0, state=RENEW
Jul 16 17:36:33	dhcp6c	93453	Sending Solicit
Jul 16 17:36:33	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:33	dhcp6c	93453	set identity association
Jul 16 17:36:33	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:33	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:33	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:33	dhcp6c	93453	set IA_PD
Jul 16 17:36:33	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:33	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=3, retrans=7611
Jul 16 17:36:33	dhcp6c	93453	Sending Solicit
Jul 16 17:36:33	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:33	dhcp6c	93453	set identity association
Jul 16 17:36:33	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:33	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:33	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:33	dhcp6c	93453	set IA_PD
Jul 16 17:36:33	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:33	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=3, retrans=8876
Jul 16 17:36:39	dhcp6c	93453	all information to be updated was canceled
Jul 16 17:36:39	dhcp6c	93453	removing an event on pppoe0, state=REBIND
Jul 16 17:36:41	dhcp6c	93453	Sending Solicit
Jul 16 17:36:41	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:41	dhcp6c	93453	set identity association
Jul 16 17:36:41	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:41	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:41	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:41	dhcp6c	93453	set IA_PD
Jul 16 17:36:41	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:41	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=4, retrans=15518
Jul 16 17:36:42	dhcp6c	93453	Sending Solicit
Jul 16 17:36:42	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:42	dhcp6c	93453	set identity association
Jul 16 17:36:42	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:42	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:42	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:42	dhcp6c	93453	set IA_PD
Jul 16 17:36:42	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:42	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=4, retrans=17814
Jul 16 17:36:49	dhcp6c	93453	all information to be updated was canceled
Jul 16 17:36:49	dhcp6c	93453	removing an event on pppoe0, state=REBIND
Jul 16 17:36:56	dhcp6c	93453	Sending Solicit
Jul 16 17:36:56	dhcp6c	93453	set client ID (len 14)
Jul 16 17:36:56	dhcp6c	93453	set identity association
Jul 16 17:36:56	dhcp6c	93453	set elapsed time (len 2)
Jul 16 17:36:56	dhcp6c	93453	set option request (len 4)
Jul 16 17:36:56	dhcp6c	93453	set IA_PD prefix
Jul 16 17:36:56	dhcp6c	93453	set IA_PD
Jul 16 17:36:56	dhcp6c	93453	send solicit to ff02::1:2%pppoe0
Jul 16 17:36:56	dhcp6c	93453	reset a timer on pppoe0, state=SOLICIT, timeo=5, retrans=32179
Jul 16 17:37:00	dhcp6c	93453	Sending Solicit
Jul 16 17:37:00	dhcp6c	93453	set client ID (len 14)
Jul 16 17:37:00	dhcp6c	93453	set identity association

YoLo88 · Jul 17, 2024, 1:38 AM

I've tried turning off gateway monitoring and that didn't make a difference.

Gertjan · Jul 17, 2024, 8:47 AM

here you were inserting this line :

@YoLo88 said in Local ISP weird behaviour w/ IPv6 via DHCP6:

[From here is almost 10 minutes (9 minutes and 54s) from when the previous lease was acquired]

the logs were still showing showing that the dhcp6c client was trying hard to get a DHCP6 lease.
First 4 x times a time out while in RENEW mode. RENEW means here : the dhcp6c client ask for a renewal of the info (lease) it already has. This is the normal sequence. See below for what I have.

Then, after several falures (probably : no answer from the server) it start to go one level lower, and rebuild the entire connection, it enters the REBIND phase, which means : it will ask for an all new DHCP6 lease. If that is done every 10 minutes, then that is pretty in the IPv4 days.

You didn't show the log lines where it eventually got eventually a valid DHCP6 lease ?
It was already on the third retry when REBINDing .....

If this happens with IPv6, then consider that catastrophic. Changing IPv6 WAN info (and prefixes for the LAns) every 10 minutes == not good.

Renewing the DHCP6 info on WAN every 10 minutes isn't unusual, though.
Here are mine :

That's every 5 minutes ! (so lucky you).
But fater 5 minutes the dhcp6c client did got an answer from my upstream DHCP6 server (it 'lives' in my ISP router box, 50 cm away from pfSense).
I cant' tell why this need to be done every 5 minutes, but ok, guess I have to hit the "learn" button in a nearby future ;)

Your issue is : it managed to get a 10 minutes DHCP6 lease ones.
And renewal is nearly impossible ....

Is it something like : after the DHPC6 lease duration time out this also impacts the lower level connection : the pppoe link ? If something happens with the pppoe link, then yeah, DHCP6 won't work, the server can't be reached, it will try, retry retyr up until the pppoe comes back again, and so on.
I'm just brainstorming here.

YoLo88 · Jul 17, 2024, 9:54 PM

@Gertjan said in Local ISP weird behaviour w/ IPv6 via DHCP6:

You didn't show the log lines where it eventually got eventually a valid DHCP6 lease ?

Thank you very much for your response!!

Those were the first set of logs @17:26. It only get's a valid IPv6 lease if I disconnect/reconnect the WAN interface via the WebUI. And it reliably does get an IPv6 address every time I do this. and then.... 10 minutes later it drops and never recovers.

This must be a setting somewhere to replicate how the Fritz box was getting IPv6 because that would ... just ... work.

YoLo88 · Jul 17, 2024, 10:01 PM

@YoLo88 said in Local ISP weird behaviour w/ IPv6 via DHCP6:

send renew to ff02::1:2%pppoe0

Is the problem this PPPoE IPv6 address - "ff02::1:2%pppoe0"

Jul 18 09:57:49	dhcp6c	86580	Sending Solicit
Jul 18 09:57:49	dhcp6c	86580	set client ID (len 14)
Jul 18 09:57:49	dhcp6c	86580	set identity association
Jul 18 09:57:49	dhcp6c	86580	set elapsed time (len 2)
Jul 18 09:57:49	dhcp6c	86580	set option request (len 4)
Jul 18 09:57:49	dhcp6c	86580	set IA_PD prefix
Jul 18 09:57:49	dhcp6c	86580	set IA_PD
Jul 18 09:57:49	dhcp6c	86580	send solicit to ff02::1:2%pppoe0
Jul 18 09:57:49	dhcp6c	86580	reset a timer on pppoe0, state=SOLICIT, timeo=1135, retrans=108036

Where the hell does that come from? I can't ping it and it doesn't look like it relates to either the fe80 link local addressing or real IPv6 addressing that I'm getting from my ISP...

YoLo88 · Jul 18, 2024, 6:14 AM

Ahh, FF02::1 is Link-local multicast address All nodes (broadcast)

Gertjan · Jul 18, 2024, 6:14 AM

@YoLo88

As this is IPV6 and IPv4 over PPPoE, did you set a MTU value less then 1500 ?

This one :

@YoLo88 said in Local ISP weird behaviour w/ IPv6 via DHCP6:

Jul 16 17:36:41 rc.gateway_alarm 99403 >>> Gateway alarm: WAN_DHCP6 (Addr:[fe80::xxx:xxxx:xxxx:xxxx]%pppoe0 Alarm:1 RTT:1.447ms RTTsd:.421ms Loss:21%)

is strange.
When the 10 minute DHCP6 lease is over, the IP6 info is still valid. Lease renewal starts to happen half way the lease duration. That is, DHCP4 works like that. When a device receives a DHCP4 lease valid for 6 hours, renewal start at 3 hours.
If that is the same for IPv6, then why ..... there is a gateway alarm = ping6 doesn't pass anymore.
I'm pretty sure that has nothing to do with the DHCP6 lease renewal.
Was the pppoe interface already reset before that gateway alarm line .
The pppoe connection itself went bad ? The pppoe renewal is a slow process. And while that's in progress, the IPv6 that goes over it can't be created.

Does the IPv4 use the same pppoe connection ? IPv4 doesn't complain / stays in a working condition ?

I'm just brainstorming here. It's years now my ISP left pppoe for what is was : perfect for the waste bin.

YoLo88 · Jul 21, 2024, 9:36 PM

@Gertjan Thanks again for your input. Much appreciated.

The MTU appears to set itself to 1492

I tried disabling gateway monitoring but it didn't make any difference.

IPv4 and IPv6 are sharing the same PPPoE connection yes, I have the "Use IPv4 connectivity as parent interface" - "Request a IPv6 prefix/information through the IPv4 connectivity link" option ticked and yes IPv4 is fine. It renews without a problem.

My ISP is garbage for tech support. I can't get anyone even remotely technical to speak to me. They just tell me to put the Fritz box back on there or it's my problem to figure out which is kind of fair enough. This IPv6 connection is stable on Fritzbox but not on PFSense. Therefore, it must be a setting in PFSense that I can tweak to fix the stability.

YoLo88 · Jul 21, 2024, 9:36 PM

What about https://redmine.pfsense.org/issues/13237 ? Some notes in there about strange behaviour that happens repeatedly unless the firewall is physically rebooted? Going to give it a cold boot now and see how that goes...

YoLo88 · Jul 21, 2024, 10:02 PM

Aaaaaaand 13 minutes of uptime and IPv6 is still stable!

YoLo88 · Jul 22, 2024, 5:35 AM

And it lasted about 50 minutes before it died and didn't recover again. So, better but still not great.

Gertjan · Jul 22, 2024, 5:35 AM

@YoLo88

So it did renew 4 times at least, and failed to do so the 5th time ?

YoLo88 · Jul 24, 2024, 10:15 AM

Looks like I was lacking "rapid commit" under advanced IP options. I tried to post instructions here but it keeps getting flagged as Spam. Check out https://www.reddit.com/r/PFSENSE/comments/1duuc6o/ipv6_troubles_unstable_pppoe_ipv6_address_via/ for the full post.