DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208
-
Looks like at least updating or reloading pfBlocker in couple with standart mpd PPPoE backend is a bit different:
2025-04-11 20:48:30.869817+03:00 unbound 50349 [50349:0] info: control cmd: load_cache 2025-04-11 20:48:30.833880+03:00 unbound 50349 [50349:0] info: control cmd: status 2025-04-11 20:48:30.802277+03:00 unbound 50349 [50349:0] info: start of service (unbound 1.22.0). 2025-04-11 20:48:30.757294+03:00 unbound 50349 [50349:0] notice: init module 1: iterator 2025-04-11 20:48:30.757242+03:00 unbound 50349 [50349:0] info: [pfBlockerNG]: init_standard script loaded 2025-04-11 20:48:29.586679+03:00 unbound 50349 [50349:0] info: [pfBlockerNG]: pfb_unbound.py script loaded 2025-04-11 20:48:29.497541+03:00 unbound 50349 [50349:0] notice: init module 0: python 2025-04-11 20:48:28.380151+03:00 unbound 39101 [39101:0] info: [pfBlockerNG]: pfb_unbound.py script exitingWill see the next hour is it stable...
Update: Working. Will test it after 8 hours switching back to the new pppoe backend to confirm.
-
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#53I'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 log2025-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 filterUntil 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
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.
-
It seems the conclusion from all this is the following.
I don't know the reason pfSense's behavior changed, but now, for the firewall to work stably, I need to enable the 'Do not wait for RA' option in the IPv6 client settings on the WAN interface, which is PPPoE -
Did you open a bug report for this?
-
@stephenw10
Not yet, should I? -
Nope I can open something. We are looking at this internally too but this is great data.
-
I'm still unable to replicate this beyond that one time I hit it.
Do you have steps to replicate? Does it still require pfBlocker?
-
@stephenw10
I don't think it still requires pfBlocker. I guess pfBlocker was just the suspect, you know… the usual suspect. Plus, it constantly pokes Unbound, which probably makes things worse. The fact that the service stopped for you too suggests there’s some kind of race condition — like a bunch of start and stop requests hit Unbound at the same time, and it ends up not knowing what to do anymore.I'm not sure it's going to be that simple to emulate. The thing is, when I captured a pcap of my PPPoE traffic to look for RA packets, it turned out that my provider is sending them every 15-25 seconds or so for some reason. I'm honestly not sure if they’re sending them on their own or if it's because pfSense is also sending a hint, I didn’t have time to dig into it all.
My setup is relatively complex: two WANs, WAN1 and WAN2, in FAILover mode, and all interfaces use LAGG for CARP compatibility. I think we can disregard all other factors, except for the fact that to reproduce this bug, PPPoE is required, and the server side should be sending RA-like informational messages to the PPPoE client — that is, the WAN interface — say, every 25 seconds?
-
Mmm, I don't see any RA packets on my PPPoE WAN here.
Or at least not over a reasonable time. -
@stephenw10
Is this what are we looking for?25.03.b.20250409.2208
/var/etc/dhcp6c_wan_script.sh without 'Do not wait for a RA' enabled
#!/bin/sh # This shell script launches /etc/rc.newwanipv6 with a interface argument. dmips=${new_domain_name_servers} dmnames=${new_domain_name} case $REASON in REBIND) ;; REQUEST|RELEASE) /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe0&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" ;; RENEW|INFO) /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe0&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" esac/var/etc/dhcp6c_wan_script.sh 'Do not wait for a RA' enabled
#!/bin/sh # This shell script launches /etc/rc.newwanipv6 with a interface argument. dmips=$(cat "/tmp/pppoe0_domain_name_servers") dmnames=$(cat "/tmp/pppoe0_new_domain_name") /bin/sleep 1 /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe0&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}"25.03.b.20250204.0023
/var/etc/dhcp6c_wan_script.sh without 'Do not wait for a RA' enabled
#!/bin/sh # This shell script launches /etc/rc.newwanipv6 with a interface argument. dmips=${new_domain_name_servers} dmnames=${new_domain_name} case $REASON in REBIND) ;; REQUEST|RELEASE) /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe0&dmnames=${dmnames}&dmips=${dmips}" ;; RENEW|INFO) esac/var/etc/dhcp6c_wan_script.sh 'Do not wait for a RA' enabled
#!/bin/sh # This shell script launches /etc/rc.newwanipv6 with a interface argument. dmips=$(cat "/tmp/pppoe0_domain_name_servers") dmnames=$(cat "/tmp/pppoe0_new_domain_name") /bin/sleep 1 /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe0&dmnames=${dmnames}&dmips=${dmips}" -
Yup could well be that.
-
Looks like 29 aprill beta fixed this behaviour.
-
Interesting. I believe there are still some edge cases there that can trigger it. We are still working on resolving it completely.
-
@stephenw10
Sure. But it looks much better then 27. April build, so definitely there's some progress. -
W w0w referenced this topic on
-
I'm on a later build now but still have the issue where different services are triggered to restart for no understandable reason. pfBlocker NG (of course), Avahi, unbound (to the point that my cache is almost always cold and even the histogram has few entries) plus NTP.
I'm also getting spurious 'hotplug' events on the LAN side (even VLANs) and these in turn also cause services to restart plus the (very few) RAs my ISP sends out triggers a change even though the established IPv4 and IPv6 details remain unchanged. It's like everything is on a hair-trigger to restart and sometimes it is like a cascade. Other times pfSense can tick along for many hours with nothing troubling the logs.
Last 500 General Log Entries. (Maximum 500) Time Process PID Message May 15 16:10:20 nginx 2025/05/15 16:10:20 [error] 46201#100603: *12017 open() "/usr/local/www/apple-touch-icon.png" failed (2: No such file or directory), client: xxxx.xxx.xxx:1:d487:e82a:32e7:abed, server: , request: "GET /apple-touch-icon.png HTTP/2.0", host: "router-7.xxxxxxxx.me:8443" May 15 16:10:20 nginx 2025/05/15 16:10:20 [error] 46201#100603: *12017 open() "/usr/local/www/apple-touch-icon-precomposed.png" failed (2: No such file or directory), client: xxxx.xxx.xxx:1:d487:e82a:32e7:abed, server: , request: "GET /apple-touch-icon-precomposed.png HTTP/2.0", host: "router-7.xxxxxxxx.me:8443" May 15 16:05:38 nginx 2025/05/15 16:05:38 [error] 46260#100604: *12013 open() "/usr/local/www/apple-touch-icon.png" failed (2: No such file or directory), client: xxxx.xxx.xxx:1:d487:e82a:32e7:abed, server: , request: "GET /apple-touch-icon.png HTTP/2.0", host: "router-7.xxxxxxxx.me:8443" May 15 16:05:38 nginx 2025/05/15 16:05:38 [error] 46260#100604: *12013 open() "/usr/local/www/apple-touch-icon-precomposed.png" failed (2: No such file or directory), client: xxxx.xxx.xxx:1:d487:e82a:32e7:abed, server: , request: "GET /apple-touch-icon-precomposed.png HTTP/2.0", host: "router-7.xxxxxxxx.me:8443" May 15 15:41:45 nginx 2025/05/15 15:41:45 [error] 46260#100604: *12010 open() "/usr/local/www/apple-touch-icon.png" failed (2: No such file or directory), client: xxxx.xxx.xxx:1:d487:e82a:32e7:abed, server: , request: "GET /apple-touch-icon.png HTTP/2.0", host: "router-7.xxxxxxxx.me:8443" May 15 15:41:45 nginx 2025/05/15 15:41:45 [error] 46260#100604: *12010 open() "/usr/local/www/apple-touch-icon-precomposed.png" failed (2: No such file or directory), client: xxxx.xxx.xxx:1:d487:e82a:32e7:abed, server: , request: "GET /apple-touch-icon-precomposed.png HTTP/2.0", host: "router-7.xxxxxxxx.me:8443" May 15 15:15:26 php_pfb 45552 [pfBlockerNG] filterlog daemon started May 15 15:15:25 tail_pfb 45236 [pfBlockerNG] Firewall Filter Service started May 15 15:15:25 php_pfb 39085 [pfBlockerNG] filterlog daemon stopped May 15 15:15:25 tail_pfb 38295 [pfBlockerNG] Firewall Filter Service stopped May 15 15:15:25 php 74778 [pfBlockerNG] Restarting firewall filter daemon May 15 15:15:25 php_pfb 31487 [pfBlockerNG] filterlog daemon stopped May 15 15:15:25 tail_pfb 30407 [pfBlockerNG] Firewall Filter Service stopped May 15 15:15:25 check_reload_status 679 Reloading filter May 15 15:15:25 php 74778 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload May 15 15:15:04 lighttpd_pfb 94273 [pfBlockerNG] DNSBL Webserver started May 15 15:15:04 lighttpd_pfb 92652 [pfBlockerNG] DNSBL Webserver stopped May 15 15:15:04 lighttpd_pfb 86295 [pfBlockerNG] DNSBL Webserver stopped May 15 15:15:04 check_reload_status 679 Syncing firewall May 15 15:15:00 php 74778 [pfBlockerNG] Starting cron process. May 15 14:03:54 check_reload_status 679 Reloading filter May 15 14:03:54 php-fpm 37396 /system.php: NTPD is starting up. May 15 14:03:53 php-fpm 37396 /system.php: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 14:03:49 php-fpm 37396 /system.php: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 14:03:48 check_reload_status 679 Syncing firewall May 15 14:03:48 php-fpm 37396 /system.php: Configuration Change: admin@xxxx.xxx.xxx:1:d487:e82a:32e7:abed (Local Database): System: May 15 12:30:17 php-cgi 66319 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI1_6_v6 does not need updating. May 15 12:30:17 php-cgi 66319 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI2_v4 does not need updating. May 15 12:30:17 php-cgi 66319 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI1_v4 does not need updating. May 15 12:30:17 php-cgi 66319 rc.update_urltables: /etc/rc.update_urltables: Starting URL table alias updates May 15 12:30:00 php-cgi 66319 rc.update_urltables: /etc/rc.update_urltables: Sleeping for 17 seconds. May 15 12:30:00 php-cgi 66319 rc.update_urltables: /etc/rc.update_urltables: Starting up. May 15 12:23:03 sshd 94207 Timeout, client not responding from user admin 10.0.1.10 port 61675 May 15 12:16:53 sshd 94207 Accepted keyboard-interactive/pam for admin from 10.0.1.10 port 61675 ssh2 May 15 12:11:26 sshd 99392 Timeout, client not responding from user admin 10.0.1.10 port 61601 May 15 11:57:32 sshd 99392 Accepted keyboard-interactive/pam for admin from 10.0.1.10 port 61601 ssh2 May 15 11:28:42 php-fpm 6073 /index.php: Successful login for user 'admin' from: xxxx.xxx.xxx:1:d487:e82a:32e7:abed (Local Database) May 15 08:12:00 check_reload_status 679 Reloading filter May 15 08:12:00 php-fpm 47458 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. May 15 08:12:00 check_reload_status 679 Reloading filter May 15 08:11:51 php-fpm 47458 /rc.newwanipv6: rc.newwanipv6: on (IP address: xxxx:xxx:xxxx:xxxx:xxxx:efff:fedc:e706) (interface: wan) (real interface: pppoe0). May 15 08:11:51 php-fpm 47458 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. May 15 08:11:50 rtsold 57226 Received RA specifying route fe80::863d:c6ff:feac:800 for interface wan(pppoe0) May 15 08:11:49 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.IPv6 with address xxxx.xxx.xxx:1:xxxx:efff:fedc:ebdc. May 15 08:11:49 avahi-daemon 74876 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 08:11:49 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.1003.IPv6 with address xxxx.xxx.xxx:2:xxxx:efff:fedc:ebdc. May 15 08:11:49 avahi-daemon 74876 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 08:11:48 check_reload_status 679 Reloading filter May 15 08:11:48 php-fpm 5087 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. May 15 08:11:48 check_reload_status 679 Reloading filter May 15 08:11:43 check_reload_status 679 Reloading filter May 15 08:11:43 check_reload_status 679 updating dyndns opt3 May 15 08:11:42 php-fpm 11672 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 08:11:41 check_reload_status 679 Reloading filter May 15 08:11:41 check_reload_status 679 Reloading filter May 15 08:11:41 check_reload_status 679 updating dyndns opt1 May 15 08:11:40 php-fpm 47458 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 08:11:40 php-fpm 11672 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1747293100] unbound[18692:0] error: bind: address already in use [1747293100] unbound[18692:0] fatal error: could not open ports' May 15 08:11:39 kernel Limiting ICMPv6 time exceeded output from 177 to 106 packets/sec May 15 08:11:38 kernel ice0: Media change is not supported. May 15 08:11:38 check_reload_status 679 Restarting IPsec tunnels May 15 08:11:38 avahi-daemon 74876 New relevant interface ice0.IPv4 for mDNS. May 15 08:11:38 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 15 08:11:38 php-fpm 11672 /rc.linkup: The command '/sbin/ifconfig 'ice0' media '10Gbase-Twinax'' returned exit code '1', the output was 'ifconfig: SIOCSIFMEDIA (media): Operation not supported by device' May 15 08:11:38 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 08:11:38 avahi-daemon 74876 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. May 15 08:11:38 avahi-daemon 74876 Interface ice0.IPv4 no longer relevant for mDNS. May 15 08:11:38 avahi-daemon 74876 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 15 08:11:38 php-fpm 11672 /rc.linkup: HOTPLUG: Configuring interface opt3 May 15 08:11:38 php-fpm 11672 /rc.linkup: DEVD Ethernet attached event for opt3 May 15 08:11:38 php-fpm 11672 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) May 15 08:11:38 check_reload_status 679 Reloading filter May 15 08:11:38 php-fpm 5087 /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1747293098] unbound[53735:0] error: bind: address already in use [1747293098] unbound[53735:0] fatal error: could not open ports' May 15 08:11:37 php-fpm 46564 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 08:11:36 php-fpm 5087 /rc.newwanipv6: rc.newwanipv6: on (IP address: xxxx:xxx:xxxx:xxxx:xxxx:efff:fedc:e706) (interface: wan) (real interface: pppoe0). May 15 08:11:36 php-fpm 5087 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. May 15 08:11:36 kernel ice0: Media change is not supported. May 15 08:11:36 check_reload_status 679 Restarting IPsec tunnels May 15 08:11:36 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. May 15 08:11:36 avahi-daemon 74876 Leaving mDNS multicast group on interface ice0.IPv6 with address xxxx.xxx.xxx:1:xxxx:efff:fedc:ebdc. May 15 08:11:36 avahi-daemon 74876 New relevant interface ice0.1003.IPv4 for mDNS. May 15 08:11:36 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 15 08:11:36 php-fpm 47458 /rc.linkup: The command '/sbin/ifconfig 'ice0' media 'autoselect'' returned exit code '1', the output was 'ifconfig: SIOCSIFMEDIA (media): Operation not supported by device' May 15 08:11:36 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 08:11:36 avahi-daemon 74876 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address xxxx.xxx.xxx:2:xxxx:efff:fedc:ebdc. May 15 08:11:36 avahi-daemon 74876 Interface ice0.1003.IPv4 no longer relevant for mDNS. May 15 08:11:36 avahi-daemon 74876 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 15 08:11:36 php-fpm 47458 /rc.linkup: HOTPLUG: Configuring interface opt1 May 15 08:11:36 php-fpm 47458 /rc.linkup: DEVD Ethernet attached event for opt1 May 15 08:11:36 php-fpm 47458 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) May 15 08:11:36 check_reload_status 679 Reloading filter May 15 08:11:36 check_reload_status 679 Reloading filter May 15 08:11:35 php-fpm 95967 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 08:11:34 php-fpm 95967 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1747293094] unbound[57538:0] error: bind: address already in use [1747293094] unbound[57538:0] fatal error: could not open ports' May 15 08:11:32 php-fpm 95967 /rc.linkup: DEVD Ethernet detached event for opt1 May 15 08:11:32 php-fpm 95967 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) May 15 08:11:32 php-fpm 46564 /rc.linkup: DEVD Ethernet detached event for opt3 May 15 08:11:32 php-fpm 46564 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) May 15 08:11:31 kernel ice0.1003: link state changed to UP May 15 08:11:31 kernel ice0: link state changed to UP May 15 08:11:31 kernel ice0: Link is up, 10 Gbps Full Duplex, Requested FEC: None, Negotiated FEC: None, Autoneg: False, Flow Control: None May 15 08:11:31 check_reload_status 679 Linkup starting ice0.1003 May 15 08:11:31 check_reload_status 679 Linkup starting ice0 May 15 08:11:31 kernel ice0.1003: link state changed to DOWN May 15 08:11:31 kernel ice0: link state changed to DOWN May 15 08:11:31 check_reload_status 679 Linkup starting ice0.1003 May 15 08:11:31 check_reload_status 679 Linkup starting ice0 May 15 07:15:24 php_pfb 51466 [pfBlockerNG] filterlog daemon started May 15 07:15:24 tail_pfb 50374 [pfBlockerNG] Firewall Filter Service started May 15 07:15:24 php_pfb 44811 [pfBlockerNG] filterlog daemon stopped May 15 07:15:24 tail_pfb 44301 [pfBlockerNG] Firewall Filter Service stopped May 15 07:15:24 php 97355 [pfBlockerNG] Restarting firewall filter daemon May 15 07:15:24 php_pfb 37950 [pfBlockerNG] filterlog daemon stopped May 15 07:15:24 tail_pfb 37374 [pfBlockerNG] Firewall Filter Service stopped May 15 07:15:24 check_reload_status 679 Reloading filter May 15 07:15:24 php 97355 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload May 15 07:15:04 lighttpd_pfb 15559 [pfBlockerNG] DNSBL Webserver started May 15 07:15:04 lighttpd_pfb 14123 [pfBlockerNG] DNSBL Webserver stopped May 15 07:15:04 lighttpd_pfb 8547 [pfBlockerNG] DNSBL Webserver stopped May 15 07:15:04 check_reload_status 679 Syncing firewall May 15 07:15:04 php 97355 /usr/local/www/pfblockerng/pfblockerng.php: Configuration Change: (system): pfBlockerNG: saving DNSBL changes May 15 07:15:00 php 97355 [pfBlockerNG] Starting cron process. May 15 05:53:00 avahi-daemon 74876 Server startup complete. Host name is Router-7.local. Local service cookie is 3249482383. May 15 05:53:00 avahi-daemon 74876 Network interface enumeration completed. May 15 05:53:00 avahi-daemon 74876 New relevant interface ice0.IPv4 for mDNS. May 15 05:53:00 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 15 05:53:00 avahi-daemon 74876 New relevant interface ice0.IPv6 for mDNS. May 15 05:53:00 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.IPv6 with address xxxx.xxx.xxx:1:xxxx:efff:fedc:ebdc. May 15 05:53:00 avahi-daemon 74876 New relevant interface ice0.1003.IPv4 for mDNS. May 15 05:53:00 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 15 05:53:00 avahi-daemon 74876 New relevant interface ice0.1003.IPv6 for mDNS. May 15 05:53:00 avahi-daemon 74876 Joining mDNS multicast group on interface ice0.1003.IPv6 with address xxxx.xxx.xxx:2:xxxx:efff:fedc:ebdc. May 15 05:53:00 avahi-daemon 74876 No service file found in /usr/local/etc/avahi/services. May 15 05:53:00 avahi-daemon 74876 avahi-daemon 0.8 starting up. May 15 05:53:00 avahi-daemon 74876 Successfully dropped root privileges. May 15 05:53:00 avahi-daemon 74876 Found user 'avahi' (UID 558) and group 'avahi' (GID 558). May 15 05:53:00 avahi-daemon 76628 avahi-daemon 0.8 exiting. May 15 05:53:00 avahi-daemon 76628 IP_DROP_MEMBERSHIP failed: Can't assign requested address May 15 05:53:00 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 15 05:53:00 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.IPv6 with address xxxx.xxx.xxx:1:xxxx:efff:fedc:ebdc. May 15 05:53:00 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 15 05:53:00 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address xxxx.xxx.xxx:2:xxxx:efff:fedc:ebdc. May 15 05:53:00 avahi-daemon 76628 Got SIGTERM, quitting. May 15 04:29:19 check_reload_status 679 Reloading filter May 15 04:29:19 php-fpm 47458 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. May 15 04:29:19 check_reload_status 679 Reloading filter May 15 04:29:10 php-fpm 47458 /rc.newwanipv6: rc.newwanipv6: on (IP address: xxxx:xxx:xxxx:xxxx:xxxx:efff:fedc:e706) (interface: wan) (real interface: pppoe0). May 15 04:29:10 php-fpm 47458 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. May 15 04:29:09 rtsold 69850 Received RA specifying route fe80::863d:c6ff:feac:800 for interface wan(pppoe0) May 15 04:29:08 avahi-daemon 76628 Joining mDNS multicast group on interface ice0.IPv6 with address xxxx.xxx.xxx:1:xxxx:efff:fedc:ebdc. May 15 04:29:08 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 04:29:08 avahi-daemon 76628 Joining mDNS multicast group on interface ice0.1003.IPv6 with address xxxx.xxx.xxx:2:xxxx:efff:fedc:ebdc. May 15 04:29:08 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 04:29:06 check_reload_status 679 Reloading filter May 15 04:29:06 php-fpm 46564 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. May 15 04:29:06 check_reload_status 679 Reloading filter May 15 04:29:02 check_reload_status 679 Reloading filter May 15 04:29:02 check_reload_status 679 updating dyndns opt1 May 15 04:29:00 php-fpm 47458 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 04:28:59 check_reload_status 679 Reloading filter May 15 04:28:59 check_reload_status 679 Reloading filter May 15 04:28:59 check_reload_status 679 updating dyndns opt3 May 15 04:28:58 php-fpm 40958 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 04:28:58 php-fpm 47458 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1747279738] unbound[88133:0] error: bind: address already in use [1747279738] unbound[88133:0] fatal error: could not open ports' May 15 04:28:56 kernel ice0: Media change is not supported. May 15 04:28:56 check_reload_status 679 Restarting IPsec tunnels May 15 04:28:56 avahi-daemon 76628 New relevant interface ice0.1003.IPv4 for mDNS. May 15 04:28:56 avahi-daemon 76628 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 15 04:28:56 php-fpm 47458 /rc.linkup: The command '/sbin/ifconfig 'ice0' media 'autoselect'' returned exit code '1', the output was 'ifconfig: SIOCSIFMEDIA (media): Operation not supported by device' May 15 04:28:56 avahi-daemon 76628 Joining mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 04:28:56 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address fe80::1:1. May 15 04:28:56 avahi-daemon 76628 Interface ice0.1003.IPv4 no longer relevant for mDNS. May 15 04:28:56 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 15 04:28:56 php-fpm 47458 /rc.linkup: HOTPLUG: Configuring interface opt1 May 15 04:28:56 php-fpm 47458 /rc.linkup: DEVD Ethernet attached event for opt1 May 15 04:28:56 php-fpm 47458 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) May 15 04:28:56 check_reload_status 679 Reloading filter May 15 04:28:56 php-fpm 46564 /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1747279736] unbound[97371:0] error: bind: address already in use [1747279736] unbound[97371:0] fatal error: could not open ports' May 15 04:28:55 php-fpm 95967 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 04:28:54 kernel ice0: Media change is not supported. May 15 04:28:54 php-fpm 46564 /rc.newwanipv6: rc.newwanipv6: on (IP address: xxxx:xxx:xxxx:xxxx:xxxx:efff:fedc:e706) (interface: wan) (real interface: pppoe0). May 15 04:28:54 php-fpm 46564 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. May 15 04:28:54 check_reload_status 679 Restarting IPsec tunnels May 15 04:28:54 avahi-daemon 76628 Joining mDNS multicast group on interface ice0.1003.IPv6 with address fe80::1:1. May 15 04:28:54 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address xxxx.xxx.xxx:2:xxxx:efff:fedc:ebdc. May 15 04:28:54 avahi-daemon 76628 New relevant interface ice0.IPv4 for mDNS. May 15 04:28:54 avahi-daemon 76628 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 15 04:28:54 php-fpm 40958 /rc.linkup: The command '/sbin/ifconfig 'ice0' media '10Gbase-Twinax'' returned exit code '1', the output was 'ifconfig: SIOCSIFMEDIA (media): Operation not supported by device' May 15 04:28:54 avahi-daemon 76628 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:efff:fedc:ebdc. May 15 04:28:54 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.IPv6 with address xxxx.xxx.xxx:1:xxxx:efff:fedc:ebdc. May 15 04:28:54 avahi-daemon 76628 Interface ice0.IPv4 no longer relevant for mDNS. May 15 04:28:54 avahi-daemon 76628 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 15 04:28:54 php-fpm 40958 /rc.linkup: HOTPLUG: Configuring interface opt3 May 15 04:28:54 php-fpm 40958 /rc.linkup: DEVD Ethernet attached event for opt3 May 15 04:28:54 php-fpm 40958 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) May 15 04:28:54 check_reload_status 679 Reloading filter May 15 04:28:54 check_reload_status 679 Reloading filter May 15 04:28:53 php-fpm 5087 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:ec:ef:dc:ed:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 15 04:28:52 php-fpm 5087 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1747279732] unbound[23995:0] error: bind: address already in use [1747279732] unbound[23995:0] fatal error: could not open ports' May 15 04:28:50 php-fpm 5087 /rc.linkup: DEVD Ethernet detached event for opt3 May 15 04:28:50 php-fpm 5087 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) May 15 04:28:50 php-fpm 95967 /rc.linkup: DEVD Ethernet detached event for opt1 May 15 04:28:50 php-fpm 95967 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) May 15 04:28:49 check_reload_status 679 Linkup starting ice0.1003 May 15 04:28:49 kernel ice0.1003: link state changed to UP May 15 04:28:49 kernel ice0: link state changed to UP May 15 04:28:49 kernel ice0: Link is up, 10 Gbps Full Duplex, Requested FEC: None, Negotiated FEC: None, Autoneg: False, Flow Control: None May 15 04:28:49 kernel ice0.1003: link state changed to DOWN May 15 04:28:49 kernel ice0: link state changed to DOWN May 15 04:28:49 check_reload_status 679 Linkup starting ice0 May 15 04:28:49 check_reload_status 679 Linkup starting ice0.1003 May 15 04:28:49 check_reload_status 679 Linkup starting ice0 May 14 23:15:26 php_pfb 78795 [pfBlockerNG] filterlog daemon started
️ -
@RobbieTT said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
May 15 08:11:31 kernel ice0: link state changed to DOWN
It's actually seeing ice0 lose link though. What's that connected to, a switch I assume? Does that also log it losing link?
-
I sent you a more complete and unredacted log by email, showing the cycle of all these services going down and up again.
There is no lost link according to the (UniFi) switch; up for 200+ days with no errors.
- ice0 (opt3) = LAN on a native SFP28 port running with 10 GbE SFP+ DAC.
- ice0.1003 (opt1) = VLAN
- igc0 (opt4) = pppoe0 / WAN link to ONT
Slightly odd to see hotplug events for a VLAN that shares the same physical DAC as the LAN.
Lots of services restarting (pretty much all of them) but unbound suffers the worst.
️ -
Mmm, in each case though the first thing logged is that ice0 and the VLAN on it lose link momentarily:
May 16 04:53:26 kernel ice0.1003: link state changed to UP May 16 04:53:26 kernel ice0: link state changed to UP May 16 04:53:26 kernel ice0: Link is up, 10 Gbps Full Duplex, Requested FEC: None, Negotiated FEC: None, Autoneg: False, Flow Control: None May 16 04:53:26 check_reload_status 679 Linkup starting ice0.1003 May 16 04:53:26 check_reload_status 679 Linkup starting ice0 May 16 04:53:26 kernel ice0.1003: link state changed to DOWN May 16 04:53:26 kernel ice0: link state changed to DOWN May 16 04:53:26 check_reload_status 679 Linkup starting ice0.1003 May 16 04:53:26 check_reload_status 679 Linkup starting ice0Can you try a different port there?
Weird that the switch doesn't show it though...
-
@stephenw10 said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
Mmm, in each case though the first thing logged is that ice0 and the VLAN on it lose link momentarily:
Can you try a different port there?Weird that the switch doesn't show it though...
Tried a different port and then the original port with a different DAC.
The fault follows whatever DAC or port is being used, no interruptions or even packets lost shown on switch (or on the pfSense GUI) and no interruptions to the upstream PPPoE server in-use IP address.
To me this looks like a pfSense issue but to be sure I have gone back to the original ports and original DAC but running on the v24.11 'current release' again. So far the symptoms have not occurred on the older firmware but need to leave it for another day or so to be sure.
️ -
@RobbieTT
Yep, maybe driver issue as well.
Something similar I have had with ix driver, like link drops but not registered on the other side. Once a week... Can't tell now is it still happening or not, since currently using different card.
Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.