No it's not the new PPPoE backend. It happened again. Now I see some pattern.
The first thing I noticed was that on the firewall clients, websites either wouldn’t open at all in the browser or only some cached versions would load. I quickly logged into pfSense to check the status of Unbound—it was running and even showing DNS servers. I checked the logs, but the last query entries were from several minutes ago and not from the clients I was using to try to open the websites. Then, a few minutes later, Unbound stopped, and the same log entry appeared again showing an attempt to load a pfBlocker script. After that, it wouldn’t start anymore. Disabling pfBlocker resolves the issue.
Update: Unbound just stopped again, even without pfBlocker enabled.
General log is spammed with:
2025-04-12 06:26:51.638991+03:00 rtsold 51255 RTSOLD Lock in place - sending SIGHUP to dhcp6c
2025-04-12 06:26:51.635417+03:00 rtsold 50386 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
2025-04-12 06:26:49.174650+03:00 php 80027 /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
2025-04-12 06:26:49.166809+03:00 php 80027 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface lagg0.99
2025-04-12 06:26:49.160456+03:00 php 80027 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
2025-04-12 06:26:48.746291+03:00 php-fpm 53325 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2x01:3bx8:3x48:xxf:a58d:367e:e74c:d339) (interface: wan) (real interface: pppoe0).
2025-04-12 06:26:48.745031+03:00 php-fpm 53325 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0 due to REQUEST.
2025-04-12 06:26:48.685327+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:48.012811+03:00 php-fpm 34113 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2ay0:1ye0:1y13:ayef:ayb8:e0ff:fe02:6559) (interface: opt3) (real interface: lagg0.99).
2025-04-12 06:26:48.011907+03:00 php-fpm 34113 /rc.newwanipv6: rc.newwanipv6: Info: starting on lagg0.99 due to REQUEST.
2025-04-12 06:26:46.192284+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:46.188918+03:00 php-fpm 2346 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
2025-04-12 06:26:46.188869+03:00 php-fpm 2346 /rc.newwanipv6: Ignoring IPsec reload since there are no tunnels on interface wan
2025-04-12 06:26:46.188745+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:45.410342+03:00 rtsold 88161 RTSOLD Lock in place - sending SIGHUP to dhcp6c
2025-04-12 06:26:45.406436+03:00 rtsold 87760 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
2025-04-12 06:26:43.053171+03:00 php 33404 /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
2025-04-12 06:26:43.045542+03:00 php 33404 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface lagg0.99
2025-04-12 06:26:43.039609+03:00 php 33404 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
2025-04-12 06:26:42.594552+03:00 php-fpm 2346 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2x01:3bx8:3x48:xxf:a58d:367e:e74c:d339) (interface: wan) (real interface: pppoe0).
2025-04-12 06:26:42.593100+03:00 php-fpm 2346 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0 due to REQUEST.
2025-04-12 06:26:41.255774+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:41.251914+03:00 php-fpm 34113 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
2025-04-12 06:26:41.251873+03:00 php-fpm 34113 /rc.newwanipv6: Ignoring IPsec reload since there are no tunnels on interface wan
2025-04-12 06:26:41.251723+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:40.358930+03:00 rtsold 64978 RTSOLD Lock in place - sending SIGHUP to dhcp6c
2025-04-12 06:26:40.356352+03:00 rtsold 64172 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
2025-04-12 06:26:37.998332+03:00 php 99595 /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
2025-04-12 06:26:37.990293+03:00 php 99595 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface lagg0.99
2025-04-12 06:26:37.984343+03:00 php 99595 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
2025-04-12 06:26:37.568279+03:00 php-fpm 34113 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2x01:3bx8:3x48:xxf:a58d:367e:e74c:d339) (interface: wan) (real interface: pppoe0).
2025-04-12 06:26:37.567158+03:00 php-fpm 34113 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0 due to REQUEST.
2025-04-12 06:26:37.513298+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:36.839346+03:00 php-fpm 43801 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2ay0:1ye0:1y13:ayef:ayb8:e0ff:fe02:6559) (interface: opt3) (real interface: lagg0.99).
2025-04-12 06:26:36.838520+03:00 php-fpm 43801 /rc.newwanipv6: rc.newwanipv6: Info: starting on lagg0.99 due to REQUEST.
2025-04-12 06:26:35.330185+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:35.326778+03:00 php-fpm 92889 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
2025-04-12 06:26:35.326736+03:00 php-fpm 92889 /rc.newwanipv6: Ignoring IPsec reload since there are no tunnels on interface wan
2025-04-12 06:26:35.326611+03:00 check_reload_status 800 Reloading filter
2025-04-12 06:26:34.507144+03:00 rtsold 12240 RTSOLD Lock in place - sending SIGHUP to dhcp6c
2025-04-12 06:26:34.500293+03:00 rtsold 11307 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
2025-04-12 06:26:32.100371+03:00 php 48496 /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
2025-04-12 06:26:32.093431+03:00 php 48496 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface lagg0.99
2025-04-12 06:26:32.087992+03:00 php 48496 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
2025-04-12 06:26:31.693700+03:00 php-fpm 92889 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2x01:3bx8:3x48:xxf:a58d:367e:e74c:d339) (interface: wan) (real interface: pppoe0).
2025-04-12 06:26:31.692566+03:00 php-fpm 92889 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0 due to REQUEST.
Unbound:
2025-04-12 06:26:54.526973+03:00 filterdns 98481 Adding Action: pf table: netgate host: acb.netgate.com
2025-04-12 06:26:54.524533+03:00 filterdns 98481 merge_config: configuration reload
2025-04-12 06:26:54.524502+03:00 filterdns 98481 Adding Action: pf table: netgate host: acb.netgate.com
2025-04-12 06:26:54.520991+03:00 filterdns 98481 merge_config: configuration reload
2025-04-12 06:26:54.520958+03:00 filterdns 98481 Adding Action: pf table: netgate host: acb.netgate.com
2025-04-12 06:26:54.517750+03:00 filterdns 98481 merge_config: configuration reload
2025-04-12 06:26:54.517716+03:00 filterdns 98481 Adding Action: pf table: netgate host: acb.netgate.com
2025-04-12 06:26:54.514953+03:00 filterdns 98481 merge_config: configuration reload
2025-04-12 06:26:54.514909+03:00 filterdns 98481 Adding Action: pf table: netgate host: acb.netgate.com
2025-04-12 06:26:54.510835+03:00 filterdns 98481 merge_config: configuration reload
2025-04-12 06:26:54.510758+03:00 filterdns 98481 Adding Action: pf table: netgate host: acb.netgate.com
2025-04-12 06:26:53.935337+03:00 unbound 41772 [41772:0] info: mesh has 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.935327+03:00 unbound 41772 [41772:0] info: server stats for thread 7: requestlist max 0 avg 0 exceeded 0 jostled 0
2025-04-12 06:26:53.935306+03:00 unbound 41772 [41772:0] info: server stats for thread 7: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.930817+03:00 unbound 41772 [41772:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.930806+03:00 unbound 41772 [41772:0] info: server stats for thread 6: requestlist max 0 avg 0 exceeded 0 jostled 0
2025-04-12 06:26:53.930784+03:00 unbound 41772 [41772:0] info: server stats for thread 6: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.926131+03:00 unbound 41772 [41772:0] info: 0.262144 0.524288 1
2025-04-12 06:26:53.926122+03:00 unbound 41772 [41772:0] info: lower(secs) upper(secs) recursions
2025-04-12 06:26:53.926114+03:00 unbound 41772 [41772:0] info: [25%]=0 median[50%]=0 [75%]=0
2025-04-12 06:26:53.926104+03:00 unbound 41772 [41772:0] info: histogram of recursion processing times
2025-04-12 06:26:53.926094+03:00 unbound 41772 [41772:0] info: average recursion processing time 0.311182 sec
2025-04-12 06:26:53.926085+03:00 unbound 41772 [41772:0] info: mesh has 12 recursion states (2 with reply, 10 detached), 2 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.926074+03:00 unbound 41772 [41772:0] info: server stats for thread 5: requestlist max 19 avg 12 exceeded 0 jostled 0
2025-04-12 06:26:53.926052+03:00 unbound 41772 [41772:0] info: server stats for thread 5: 3 queries, 0 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.921550+03:00 unbound 41772 [41772:0] info: mesh has 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.921540+03:00 unbound 41772 [41772:0] info: server stats for thread 4: requestlist max 0 avg 0 exceeded 0 jostled 0
2025-04-12 06:26:53.921519+03:00 unbound 41772 [41772:0] info: server stats for thread 4: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.916866+03:00 unbound 41772 [41772:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.916856+03:00 unbound 41772 [41772:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0
2025-04-12 06:26:53.916832+03:00 unbound 41772 [41772:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.911784+03:00 unbound 41772 [41772:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.911774+03:00 unbound 41772 [41772:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
2025-04-12 06:26:53.911750+03:00 unbound 41772 [41772:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.906817+03:00 unbound 41772 [41772:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.906806+03:00 unbound 41772 [41772:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
2025-04-12 06:26:53.906781+03:00 unbound 41772 [41772:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.901564+03:00 unbound 41772 [41772:0] info: 0.524288 1.000000 1
2025-04-12 06:26:53.901556+03:00 unbound 41772 [41772:0] info: lower(secs) upper(secs) recursions
2025-04-12 06:26:53.901548+03:00 unbound 41772 [41772:0] info: [25%]=0 median[50%]=0 [75%]=0
2025-04-12 06:26:53.901538+03:00 unbound 41772 [41772:0] info: histogram of recursion processing times
2025-04-12 06:26:53.901530+03:00 unbound 41772 [41772:0] info: average recursion processing time 0.828461 sec
2025-04-12 06:26:53.901521+03:00 unbound 41772 [41772:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
2025-04-12 06:26:53.901509+03:00 unbound 41772 [41772:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
2025-04-12 06:26:53.901478+03:00 unbound 41772 [41772:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
2025-04-12 06:26:53.899626+03:00 unbound 41772 [41772:0] info: service stopped (unbound 1.22.0).
2025-04-12 06:26:53.744584+03:00 unbound 41772 [41772:4] info: query response was nodata ANSWER
2025-04-12 06:26:53.744568+03:00 unbound 41772 [41772:4] info: reply from <steamserver.net.> 23.74.25.65#53
I've started it manually and it works again...
UPDATE2:
Playing now with IPv6 enabled/disabled globally
unbound:
2025-04-12 08:01:11.944259+03:00 unbound 77333 [77333:0] debug: join success 7
2025-04-12 08:01:11.944165+03:00 unbound 77333 [77333:7] debug: got control cmd quit
2025-04-12 08:01:11.944124+03:00 unbound 77333 [77333:7] debug: cache memory msg=132184 rrset=132184 infra=11266 val=0
general log:
2025-04-12 08:01:13.482557+03:00 rtsold 51709 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
2025-04-12 08:01:10.818324+03:00 php 54984 /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
2025-04-12 08:01:10.813243+03:00 php 54984 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface lagg0.99
2025-04-12 08:01:10.809139+03:00 php 54984 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
2025-04-12 08:01:10.537541+03:00 php-fpm 24416 /rc.newwanipv6: rc.newwanipv6: on (IP address: xxxxxxx:f09e:cc1c) (interface: wan) (real interface: pppoe0).
2025-04-12 08:01:10.536925+03:00 php-fpm 24416 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0 due to REQUEST.
It looks like ppp-ipv6 is triggering some function in a loop that keeps restarting unbound. Now testing with IPv6 disabled globally.
Update 3:
and ppp-ipv6 is triggered by this&?
2025-04-12 11:04:52.871941+03:00 rtsold 1033 RTSOLD Lock in place - sending SIGHUP to dhcp6c
2025-04-12 11:04:52.870315+03:00 rtsold 429 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
IP adresses not changing during this sequence, but for some reason it wants to restart unbound and other things?
Also, when disabling Ipv6 in GUI, it continiues to spam the system log
2025-04-12 11:10:08.917445+03:00 php 67708 /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0)
2025-04-12 11:10:08.912200+03:00 php 67708 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface lagg0.99
2025-04-12 11:10:08.908024+03:00 php 67708 /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0
2025-04-12 11:10:08.620777+03:00 php-fpm 76303 /rc.newwanipv6: rc.newwanipv6: on (IP address: 20bb:x:d248:ffff:796b:f302:330f:3e20) (interface: wan) (real interface: pppoe0).
2025-04-12 11:10:08.620121+03:00 php-fpm 76303 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0 due to REQUEST.
2025-04-12 11:10:08.385746+03:00 php-fpm 6614 /rc.filter_configure_sync: Omitting gateway from filter ruleset. Group: "failoverIPv6" Gateway: "WAN_DHCP6" IP: "fe80::669e:f3ff:fe94:dd00%pppoe0"
2025-04-12 11:10:08.270271+03:00 php-fpm 36313 /rc.filter_configure_sync: Omitting gateway from filter ruleset. Group: "failoverIPv6" Gateway: "WAN_DHCP6" IP: "fe80::669e:f3ff:fe94:dd00%pppoe0"
2025-04-12 11:10:07.209934+03:00 php-fpm 6614 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
2025-04-12 11:10:07.209896+03:00 php-fpm 6614 /rc.newwanipv6: Ignoring IPsec reload since there are no tunnels on interface wan
2025-04-12 11:10:07.208511+03:00 check_reload_status 790 Reloading filter
2025-04-12 11:10:07.208491+03:00 check_reload_status 790 Restarting OpenVPN tunnels/interfaces
2025-04-12 11:10:07.208460+03:00 check_reload_status 790 Restarting IPsec tunnels
2025-04-12 11:10:07.205988+03:00 rc.gateway_alarm 7070 >>> Gateway alarm: WAN2_DHCP6 (Addr:fe80::72b3:d5ff:fe10:36e%lagg0.99 Alarm:1 RTT:0ms RTTsd:0ms Loss:100%)
2025-04-12 11:10:07.183160+03:00 check_reload_status 790 Reloading filter
2025-04-12 11:10:07.183143+03:00 check_reload_status 790 Restarting OpenVPN tunnels/interfaces
2025-04-12 11:10:07.183120+03:00 check_reload_status 790 Restarting IPsec tunnels
2025-04-12 11:10:07.183032+03:00 check_reload_status 790 updating dyndns WAN_DHCP6
2025-04-12 11:10:07.180970+03:00 rc.gateway_alarm 98737 >>> Gateway alarm: WAN_DHCP6 (Addr:fe80::669e:f3ff:fe94:dd00%pppoe0 Alarm:1 RTT:0ms RTTsd:0ms Loss:100%)
2025-04-12 11:10:05.895979+03:00 rtsold 95879 RTSOLD Lock in place - sending SIGHUP to dhcp6c
2025-04-12 11:10:05.894362+03:00 rtsold 94970 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
2025-04-12 11:10:05.413847+03:00 rtsold 47846 <cap_rssend> sendmsg on pppoe0: Permission denied
2025-04-12 11:10:04.675445+03:00 php-fpm 18968 /rc.dyndns.update: phpDynDNS (910681): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2025-04-12 11:10:03.999576+03:00 php-fpm 65252 /rc.filter_configure_sync: Omitting gateway from filter ruleset. Group: "failoverIPv6" Gateway: "WAN_DHCP6" IP: "fe80::669e:f3ff:fe94:dd00%pppoe0"
2025-04-12 11:10:03.670840+03:00 php-fpm 18968 /rc.dyndns.update: phpDynDNS (bbbb): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2025-04-12 11:10:02.939346+03:00 check_reload_status 790 Reloading filter
Until I reboot firewall
Update4:
2025-04-12 11:10:05.894362+03:00 rtsold 94970 Received RA specifying route fe80::669e:f3ff:fe94:dd00 for interface wan(pppoe0)
This is it — at least on snapshot 25.03.b.20250409.2208. When the "Do not wait for RA" option is not enabled
8404b513-5511-4204-8374-c004a0f2ab08-image.png
it causes /rc.newwanipv6 to be triggered every few seconds when RA INFO packets are received, even if there are no changes in the IP address.
On snapshot 25.03.b.20250204.0023, the behavior is normal — the connection is established and doesn't constantly trigger rc.newwanipv6, even with the option disabled.
I've now enabled "Do not wait for RA" on 25.03.b.20250409.2208 — continuing to test.