DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208
-
Hmm, it could be something weird in the ice driver I guess. I don't yet have anything using that to test with. Kernel link down is normally a very specific event though.
The only other situation I've seen generate those is with Snort/Suricata in in-line mode where the virtual interface can change state when it restarts.
-
@stephenw10
It's something we saw a while back with a race condition that was traced and resolved only after taking kernel dumps. I'm sure it is not the same issue though as that was more significant and could even cause a crash, just that pfSense has been able to trigger a similar spurious hotplug event before.️
-
Yeah that was not quite the same. The interface triggering it did actually change status, pppoe went down in that case. ice0 should not change state here unless it really does lose link. And if it does then I'd expect the other side to log it also. You might try resaving the ice0 interface, which should bump the link state, and then checking how that is shown in the logs at both ends of the link. Just to be sure the switch does log it.
-
@stephenw10
Ok, what command do I need to re-save the ice0 interface?As a serious bit of utter trivia I also get this harmless error
May 15 22:23:47 nginx 2025/05/15 22:23:47 [error] 46260#100604: *12679 open() "/usr/local/www/apple-touch-icon.png" failed (2: No such file or directory), client: xxxx:abed, server: , request: "GET /apple-touch-icon.png HTTP/2.0", host: "router-7.xxxx.me:8443" May 15 22:23:47 nginx 2025/05/15 22:23:47 [error] 46260#100604: *12679 open() "/usr/local/www/apple-touch-icon-precomposed.png" failed (2: No such file or directory), client:
The actual path is: /usr/local/www/apple-touch/ to find the icon.png files.
️
-
I'd just resave the assigned interface in the GUI. But you could also just ifconfig down/up the interface at the CLI.
Do those icons actually fail to display on the client?
It could just be the client device(s) looking for those in multiple locations.
-
As I'm still running v24.11 (still no hotplug events etc) I re-saved the interface for comparison later:
Time Process PID Message May 23 19:29:21 php_pfb 44380 [pfBlockerNG] filterlog daemon started May 23 19:29:20 tail_pfb 44127 [pfBlockerNG] Firewall Filter Service started May 23 19:29:20 lighttpd_pfb 42103 [pfBlockerNG] DNSBL Webserver started May 23 19:29:20 php_pfb 39811 [pfBlockerNG] filterlog daemon stopped May 23 19:29:20 tail_pfb 38493 [pfBlockerNG] Firewall Filter Service stopped May 23 19:29:20 lighttpd_pfb 38314 [pfBlockerNG] DNSBL Webserver stopped May 23 19:29:20 rtsold 15216 Received RA specifying route fe80::xxx:xxxx:xxxx:b100 for interface wan(pppoe0) May 23 19:29:20 avahi-daemon 71022 Server startup complete. Host name is Router-7.local. Local service cookie is 830558610. May 23 19:29:20 avahi-daemon 71022 Network interface enumeration completed. May 23 19:29:20 avahi-daemon 71022 New relevant interface ice0.IPv4 for mDNS. May 23 19:29:20 avahi-daemon 71022 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 23 19:29:20 avahi-daemon 71022 New relevant interface ice0.IPv6 for mDNS. May 23 19:29:20 avahi-daemon 71022 Joining mDNS multicast group on interface ice0.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:29:20 avahi-daemon 71022 New relevant interface ice0.1003.IPv4 for mDNS. May 23 19:29:20 avahi-daemon 71022 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 23 19:29:20 avahi-daemon 71022 New relevant interface ice0.1003.IPv6 for mDNS. May 23 19:29:20 avahi-daemon 71022 Joining mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:29:20 avahi-daemon 71022 No service file found in /usr/local/etc/avahi/services. May 23 19:29:20 avahi-daemon 71022 avahi-daemon 0.8 starting up. May 23 19:29:20 avahi-daemon 71022 Successfully dropped root privileges. May 23 19:29:20 avahi-daemon 71022 Found user 'avahi' (UID 558) and group 'avahi' (GID 558). May 23 19:29:19 php-fpm 16922 /rc.start_packages: Starting service avahi May 23 19:29:19 avahi-daemon 35171 avahi-daemon 0.8 exiting. May 23 19:29:19 avahi-daemon 35171 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 23 19:29:19 avahi-daemon 35171 Leaving mDNS multicast group on interface ice0.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:29:19 avahi-daemon 35171 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 23 19:29:19 avahi-daemon 35171 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:29:19 avahi-daemon 35171 Got SIGTERM, quitting. May 23 19:29:19 php-fpm 16922 /rc.start_packages: Stopping service avahi May 23 19:29:19 php-fpm 16922 /rc.start_packages: Restarting/Starting all packages. May 23 19:29:19 avahi-daemon 35171 Joining mDNS multicast group on interface ice0.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:29:19 avahi-daemon 35171 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. May 23 19:29:19 avahi-daemon 35171 Joining mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:29:19 avahi-daemon 35171 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address fe80::1:1. May 23 19:29:18 check_reload_status 667 Reloading filter May 23 19:29:18 check_reload_status 667 Reloading filter May 23 19:29:18 check_reload_status 667 Starting packages May 23 19:29:18 php-fpm 62604 /rc.newwanipv6: Netgate pfSense Plus package system has detected an IP change or dynamic WAN reconnection - -> 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc - Restarting packages. May 23 19:29:18 php-fpm 62604 /rc.newwanipv6: Creating rrd update script May 23 19:29:18 php-fpm 62604 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. May 23 19:29:17 php-fpm 62604 /rc.newwanipv6: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 23 19:29:15 php_pfb 5629 [pfBlockerNG] filterlog daemon started May 23 19:29:15 tail_pfb 5244 [pfBlockerNG] Firewall Filter Service started May 23 19:29:15 lighttpd_pfb 2862 [pfBlockerNG] DNSBL Webserver started May 23 19:29:15 php_pfb 978 [pfBlockerNG] filterlog daemon stopped May 23 19:29:15 tail_pfb 217 [pfBlockerNG] Firewall Filter Service stopped May 23 19:29:15 lighttpd_pfb 23 [pfBlockerNG] DNSBL Webserver stopped May 23 19:29:15 avahi-daemon 35171 Server startup complete. Host name is Router-7.local. Local service cookie is 354485446. May 23 19:29:15 avahi-daemon 35171 Network interface enumeration completed. May 23 19:29:15 avahi-daemon 35171 New relevant interface ice0.IPv4 for mDNS. May 23 19:29:15 avahi-daemon 35171 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 23 19:29:15 avahi-daemon 35171 New relevant interface ice0.IPv6 for mDNS. May 23 19:29:15 avahi-daemon 35171 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. May 23 19:29:15 avahi-daemon 35171 New relevant interface ice0.1003.IPv4 for mDNS. May 23 19:29:15 avahi-daemon 35171 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 23 19:29:15 avahi-daemon 35171 New relevant interface ice0.1003.IPv6 for mDNS. May 23 19:29:15 avahi-daemon 35171 Joining mDNS multicast group on interface ice0.1003.IPv6 with address fe80::1:1. May 23 19:29:15 avahi-daemon 35171 No service file found in /usr/local/etc/avahi/services. May 23 19:29:15 avahi-daemon 35171 avahi-daemon 0.8 starting up. May 23 19:29:15 avahi-daemon 35171 Successfully dropped root privileges. May 23 19:29:15 avahi-daemon 35171 Found user 'avahi' (UID 558) and group 'avahi' (GID 558). May 23 19:29:15 check_reload_status 667 Reloading filter May 23 19:29:14 php-fpm 79962 /rc.start_packages: Starting service avahi May 23 19:29:14 avahi-daemon 18747 avahi-daemon 0.8 exiting. May 23 19:29:14 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 23 19:29:14 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. May 23 19:29:14 avahi-daemon 18747 IP_DROP_MEMBERSHIP failed: Can't assign requested address May 23 19:29:14 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 23 19:29:14 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address fe80::1:1. May 23 19:29:14 avahi-daemon 18747 Got SIGTERM, quitting. May 23 19:29:14 php-fpm 79962 /rc.start_packages: Stopping service avahi May 23 19:29:14 php-fpm 79962 /rc.start_packages: Restarting/Starting all packages. May 23 19:29:13 check_reload_status 667 Starting packages May 23 19:29:13 php-fpm 46785 /interfaces.php: Creating rrd update script May 23 19:29:13 check_reload_status 667 Reloading filter May 23 19:29:12 php-fpm 46785 /interfaces.php: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 23 19:29:11 php-fpm 46785 /interfaces.php: Resyncing OpenVPN instances for interface LAN. May 23 19:29:08 php-fpm 46785 /interfaces.php: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 23 19:29:05 php-fpm 62604 /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1748024945] unbound[17454:0] error: bind: address already in use [1748024945] unbound[17454:0] fatal error: could not open ports' May 23 19:29:04 php-fpm 62604 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc) (interface: wan) (real interface: pppoe0). May 23 19:29:04 php-fpm 62604 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. May 23 19:29:04 avahi-daemon 18747 Joining mDNS multicast group on interface ice0.1003.IPv6 with address fe80::1:1. May 23 19:29:04 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:29:04 check_reload_status 667 updating dyndns opt3 May 23 19:29:03 php-fpm 46785 /interfaces.php: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 23 19:29:00 check_reload_status 667 Restarting IPsec tunnels May 23 19:28:59 nginx 2025/05/23 19:28:59 [crit] 62339#100601: *361 SSL_write() failed (13: Permission denied) while processing HTTP/2 connection, client: 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:2b90, server: [::]:8443 May 23 19:28:57 kernel ice0: Media change is not supported. May 23 19:28:57 avahi-daemon 18747 New relevant interface ice0.IPv4 for mDNS. May 23 19:28:57 avahi-daemon 18747 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 23 19:28:57 php-fpm 46785 /interfaces.php: The command '/sbin/ifconfig 'ice0' media '10Gbase-Twinax'' returned exit code '1', the output was 'ifconfig: SIOCSIFMEDIA (media): Operation not supported by device' May 23 19:28:57 avahi-daemon 18747 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. May 23 19:28:57 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. May 23 19:28:57 avahi-daemon 18747 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. May 23 19:28:57 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. May 23 19:28:57 avahi-daemon 18747 Interface ice0.IPv4 no longer relevant for mDNS. May 23 19:28:57 avahi-daemon 18747 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 23 19:28:52 check_reload_status 667 Syncing firewall May 23 19:28:52 php-fpm 79962 /interfaces.php: Configuration Change: admin@2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:2b90(Local Database): Interfaces settings changed May 23 19:28:06 php-fpm 16922 /interfaces_assign.php: Creating rrd update script May 23 19:28:06 check_reload_status 667 Syncing firewall May 23 19:28:06 php-fpm 16922 /interfaces_assign.php: Configuration Change: admin@2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:2b90(Local Database): Interfaces assignment settings changed
Nothing of note to my eyes on the old firmware and the brief upset was noted by the switch. No 'hotplug' events during the interface re-save / change either.
I'll switch to the 25.03 beta later this evening and re-run this test point.
️
-
@stephenw10 said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
Do those icons actually fail to display on the client?
Everything seems to work ok so I think these are just nuisance warnings in the logs. They could be avoided if the files were held in the normal directory, rather than in a layer further down. All the others are in the correct directory (eg for Android) but the Apple png files have been clustered in their own directory.
️
-
@stephenw10 said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
Yeah that was not quite the same. The interface triggering it did actually change status, pppoe went down in that case. ice0 should not change state here unless it really does lose link. And if it does then I'd expect the other side to log it also. You might try resaving the ice0 interface, which should bump the link state, and then checking how that is shown in the logs at both ends of the link. Just to be sure the switch does log it.
Bumping the link state was recognised by the switch.
Running the old firmware v24.11 there were no lost link / hotplug events.
For fun I pulled the DAC cable to trigger an actual fault and noticed the syntax is different for a real event, with module guidance from the kernel etc:
May 24 15:00:01 check_reload_status 667 Reloading filter May 24 15:00:01 php-fpm 52132 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. May 24 15:00:01 check_reload_status 667 Reloading filter May 24 14:59:52 php-fpm 52132 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2a02:xxxx:xxxx:xxxx:xxxx:xxxx:e706) (interface: wan) (real interface: pppoe0). May 24 14:59:52 php-fpm 52132 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. May 24 14:59:51 rtsold 4675 Received RA specifying route fe80::redacted:b100 for interface wan(pppoe0) May 24 14:59:50 avahi-daemon 8483 Joining mDNS multicast group on interface ice0.IPv6 with address 2a02:xxxx:xxxx:xxxx:xxxx:ebdc. May 24 14:59:50 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. May 24 14:59:50 avahi-daemon 8483 Joining mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxxx:xxxx:x:xxxx:xxxx:ebdc. May 24 14:59:50 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. May 24 14:59:49 check_reload_status 667 Reloading filter May 24 14:59:49 php-fpm 62793 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. May 24 14:59:49 check_reload_status 667 Reloading filter May 24 14:59:45 check_reload_status 667 Reloading filter May 24 14:59:45 check_reload_status 667 updating dyndns opt1 May 24 14:59:44 php-fpm 52132 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 24 14:59:43 check_reload_status 667 Reloading filter May 24 14:59:43 check_reload_status 667 Reloading filter May 24 14:59:42 check_reload_status 667 updating dyndns opt3 May 24 14:59:41 php-fpm 83155 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 24 14:59:39 php-fpm 83155 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1748095179] unbound[69207:0] error: bind: address already in use [1748095179] unbound[69207:0] fatal error: could not open ports' May 24 14:59:39 php-fpm 62793 /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1748095179] unbound[69113:0] error: bind: address already in use [1748095179] unbound[69113:0] fatal error: could not open ports' May 24 14:59:38 php-fpm 62793 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2a02:xxxx:xxxx:xxxx:xxxx:xxxx:e706) (interface: wan) (real interface: pppoe0). May 24 14:59:38 php-fpm 62793 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. May 24 14:59:38 check_reload_status 667 Restarting IPsec tunnels May 24 14:59:38 check_reload_status 667 Restarting IPsec tunnels May 24 14:59:38 kernel ice0: Media change is not supported. May 24 14:59:38 kernel ice0: Media change is not supported. May 24 14:59:37 avahi-daemon 8483 New relevant interface ice0.1003.IPv4 for mDNS. May 24 14:59:37 avahi-daemon 8483 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 24 14:59:37 php-fpm 52132 /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 24 14:59:37 avahi-daemon 8483 New relevant interface ice0.IPv4 for mDNS. May 24 14:59:37 avahi-daemon 8483 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 24 14:59:37 avahi-daemon 8483 Joining mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. May 24 14:59:37 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxxx:xxxx:x:xxxx:xxxx:ebdc. May 24 14:59:37 php-fpm 83155 /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 24 14:59:37 avahi-daemon 8483 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. May 24 14:59:37 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.IPv6 with address 2a02:xxxx:xxxx:xxxx:xxxx:ebdc. May 24 14:59:37 avahi-daemon 8483 Interface ice0.IPv4 no longer relevant for mDNS. May 24 14:59:37 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 24 14:59:37 php-fpm 83155 /rc.linkup: HOTPLUG: Configuring interface opt3 May 24 14:59:37 php-fpm 83155 /rc.linkup: DEVD Ethernet attached event for opt3 May 24 14:59:37 php-fpm 83155 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) May 24 14:59:37 avahi-daemon 8483 Interface ice0.1003.IPv4 no longer relevant for mDNS. May 24 14:59:37 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 24 14:59:37 php-fpm 52132 /rc.linkup: HOTPLUG: Configuring interface opt1 May 24 14:59:37 php-fpm 52132 /rc.linkup: DEVD Ethernet attached event for opt1 May 24 14:59:37 php-fpm 52132 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) May 24 14:59:36 kernel ice0.1003: link state changed to UP May 24 14:59:36 kernel ice0: link state changed to UP May 24 14:59:36 kernel ice0: Link is up, 10 Gbps Full Duplex, Requested FEC: None, Negotiated FEC: None, Autoneg: False, Flow Control: None May 24 14:59:36 check_reload_status 667 Linkup starting ice0.1003 May 24 14:59:36 check_reload_status 667 Linkup starting ice0 May 24 14:59:25 check_reload_status 667 Reloading filter May 24 14:59:24 php-fpm 13966 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 24 14:59:23 check_reload_status 667 Reloading filter May 24 14:59:23 check_reload_status 667 Reloading filter May 24 14:59:21 php-fpm 64480 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' May 24 14:59:20 php-fpm 64480 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1748095160] unbound[49580:0] error: bind: address already in use [1748095160] unbound[49580:0] fatal error: could not open ports' May 24 14:59:19 php-fpm 64480 /rc.linkup: DEVD Ethernet detached event for opt1 May 24 14:59:19 php-fpm 64480 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) May 24 14:59:19 php-fpm 13966 /rc.linkup: DEVD Ethernet detached event for opt3 May 24 14:59:19 php-fpm 13966 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) May 24 14:59:18 kernel ice0: Possible Solution 2: If the problem persists, use a cable/module that is found in the supported modules and cables list for this device. May 24 14:59:18 kernel ice0: Possible Solution 1: Check that the module is inserted correctly. May 24 14:59:18 kernel ice0: Module is not present. May 24 14:59:18 kernel ice0.1003: link state changed to DOWN May 24 14:59:18 kernel ice0: link state changed to DOWN May 24 14:59:18 kernel ice0: Possible Solution 2: If the problem persists, use a cable/module that is found in the supported modules and cables list for this device. May 24 14:59:18 kernel ice0: Possible Solution 1: Check that the module is inserted correctly. May 24 14:59:18 kernel ice0: Module is not present. May 24 14:59:18 check_reload_status 667 Linkup starting ice0.1
I'm not sure what is going on with the unexplained 'errant' hotplug events, other than there is a loose periodicity to them. Certainly they are very brief in nature. These SFP28 interfaces are direct from the CPU itself, which did have a microcode update bundled with the beta firmware.
️
-
A couple of days running v24.11 and the hotplug / dns resolver and services restarting does not happen on the older firmware, only with v25.03b.
Other than the actual physical DAC disconnections yesterday the system log is refreshingly empty:
May 25 12:30:36 php-fpm 27341 /index.php: Successful login for user 'admin' from: 2a02:redcted:d57f (Local Database) May 25 12:30:06 php-cgi 8192 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI1_6_v6 does not need updating. May 25 12:30:06 php-cgi 8192 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI2_v4 does not need updating. May 25 12:30:06 php-cgi 8192 rc.update_urltables: /etc/rc.update_urltables: pfB_PRI1_v4 does not need updating. May 25 12:30:06 php-cgi 8192 rc.update_urltables: /etc/rc.update_urltables: Starting URL table alias updates May 25 12:30:00 php-cgi 8192 rc.update_urltables: /etc/rc.update_urltables: Sleeping for 6 seconds. May 25 12:30:00 php-cgi 8192 rc.update_urltables: /etc/rc.update_urltables: Starting up. May 25 07:15:23 php 5865 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload May 25 07:15:00 php 5865 [pfBlockerNG] Starting cron process. May 25 05:53:00 avahi-daemon 81100 Server startup complete. Host name is Router-7.local. Local service cookie is 2redacted1. May 25 05:53:00 avahi-daemon 81100 Network interface enumeration completed. May 25 05:53:00 avahi-daemon 81100 New relevant interface ice0.IPv4 for mDNS. May 25 05:53:00 avahi-daemon 81100 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 25 05:53:00 avahi-daemon 81100 New relevant interface ice0.IPv6 for mDNS. May 25 05:53:00 avahi-daemon 81100 Joining mDNS multicast group on interface ice0.IPv6 with address 2a02:redacted:ebdc. May 25 05:53:00 avahi-daemon 81100 New relevant interface ice0.1003.IPv4 for mDNS. May 25 05:53:00 avahi-daemon 81100 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 25 05:53:00 avahi-daemon 81100 New relevant interface ice0.1003.IPv6 for mDNS. May 25 05:53:00 avahi-daemon 81100 Joining mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:redacted:ebdc. May 25 05:53:00 avahi-daemon 81100 No service file found in /usr/local/etc/avahi/services. May 25 05:53:00 avahi-daemon 81100 avahi-daemon 0.8 starting up. May 25 05:53:00 avahi-daemon 81100 Successfully dropped root privileges. May 25 05:53:00 avahi-daemon 81100 Found user 'avahi' (UID 558) and group 'avahi' (GID 558). May 25 05:53:00 avahi-daemon 8483 avahi-daemon 0.8 exiting. May 25 05:53:00 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. May 25 05:53:00 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.IPv6 with address 2a02:redacted:ebdc. May 25 05:53:00 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. May 25 05:53:00 avahi-daemon 8483 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:redacted:ebdc. May 25 05:53:00 avahi-daemon 8483 Got SIGTERM, quitting. May 25 01:15:24 php 47884 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload May 25 01:15:00 php 47884 [pfBlockerNG] Starting cron process. May 24 19:15:30 php 15877 [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload May 24 19:15:00 php 15877 [pfBlockerNG] Starting cron process. May 24 15:00:01 check_reload_status 667 Reloading filter May 24 15:00:01 php-fpm 52132 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.
I'll switch back to the beta to see what else crops up.
️
-
Hmm, I guess I would expect to see a different set of logs if the module is removed from the NIC locally since that doesn't happen if it just loses link.
You might try removing the module at the other end and see what is shown then.
Otherwise we might be looking at a difference in the driver. I doubt the CPU microcode would change anything there.
-
Having tried all possible combinations now the only clear point is that this does not happen with v24.11 and that the fault is limited to v23.03b.
The underlying cause alludes me, not helped by how brief the hiccup is, with everything happening in sub-1 sec. As soon as the
check_reload_status
command is sent you get the first event in the log showing that the link-up is starting:May 28 05:30:08 Router-7 check_reload_status[678]: Linkup starting ice0 May 28 05:30:08 Router-7 check_reload_status[678]: Linkup starting ice0.1003 May 28 05:30:08 Router-7 kernel: ice0: link state changed to DOWN May 28 05:30:08 Router-7 kernel: ice0.1003: link state changed to DOWN May 28 05:30:08 Router-7 check_reload_status[678]: Linkup starting ice0 May 28 05:30:08 Router-7 check_reload_status[678]: Linkup starting ice0.1003 May 28 05:30:08 Router-7 kernel: ice0: Link is up, 10 Gbps Full Duplex, Requested FEC: None, Negotiated FEC: None, Autoneg: False, Flow Control: None May 28 05:30:08 Router-7 kernel: ice0: link state changed to UP May 28 05:30:08 Router-7 kernel: ice0.1003: link state changed to UP May 28 05:30:09 Router-7 php-fpm[9624]: /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) [etc...]
The periodicity seems to align with either pfSense doing something else or aligning with a distinct time. It's not random, there is loose pattern to it.
Is there a way to sub-second timestamps on the system log?
️
-
Hmm, gotta be some driver difference.
Are you using the ice_dpp module?
-
@RobbieTT said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
Is there a way to sub-second timestamps on the system log?
Sure. Select LOG Message Format as RFC5424 with RFC3339
-
@stephenw10 said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
Hmm, gotta be some driver difference.
Are you using the ice_dpp module?
I have a single loader tunable active:
/boot/loader.conf.local ice_ddp_load="YES"
ifconfig:
ice0: flags=1008843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST,LOWER_UP> metric 0 mtu 9000 description: LAN options=4e100bb<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,VLAN_HWFILTER,RXCSUM_IPV6,TXCSUM_IPV6,HWSTATS,MEXTPG> ether 3c:xx:xx:xx:xx:dc inet 10.0.1.1 netmask 0xffffff00 broadcast 10.0.1.255 inet6 fe80::xxxx:xxxx:xxxx:ebdc%ice0 prefixlen 64 scopeid 0x6 inet6 fe80::1:1%ice0 prefixlen 64 scopeid 0x6 inet6 2a02:xxx:xxxx:1:xxxx:xxxx:xxxx:ebdc prefixlen 64 media: Ethernet autoselect (10Gbase-Twinax <full-duplex>) status: active nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL> drivername: ice0 plugged: SFP/SFP+/SFP28 Unknown (Copper pigtail) vendor: ipolex PN: SFP-H10GB-CU1M SN: WTS11J72204 DATE: 2019-07-24
dmesg | grep ice0:
ice0: <Intel(R) Ethernet Connection E823-L for SFP - 1.43.2-k> mem 0xf0000000-0xf7ffffff,0xfa010000-0xfa01ffff at device 0.0 numa-domain 0 on pci11 ice0: Loading the iflib ice driver ice0: The DDP package was successfully loaded: ICE OS Default Package version 1.3.41.0, track id 0xc0000001. ice0: fw 5.5.17 api 1.7 nvm 2.28 etid 80011e36 netlist 0.1.7000-1.25.0.f083a9d5 oem 1.3200.0 ice0: Using 8 Tx and Rx queues ice0: Reserving 8 MSI-X interrupts for iRDMA ice0: Using MSI-X interrupts with 17 vectors ice0: Using 1024 TX descriptors and 1024 RX descriptors ice0: Ethernet address: 3c:xx:xx:xx:xx:dc ice0: ice_add_rss_cfg on VSI 0 could not configure every requested hash type ice0: Firmware LLDP agent disabled ice0: link state changed to UP ice0: Link is up, 10 Gbps Full Duplex, Requested FEC: None, Negotiated FEC: None, Autoneg: False, Flow Control: None ice0: netmap queues/slots: TX 8/1024, RX 8/1024
️
-
@w0w said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
@RobbieTT said in DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208:
Sure. Select LOG Message Format as RFC5424 with RFC3339
Perfect, thank you.
️
-
Recent logs, now with extra fidelity... if it helps:
2025-05-29 09:01:45.064334+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:45.057215+01:00 php-fpm 44701 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. 2025-05-29 09:01:45.056929+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:35.348096+01:00 php-fpm 44701 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2a02:xxxx:feed:xxxx:xxxx:xxxx:xxxx:e706) (interface: wan) (real interface: pppoe0). 2025-05-29 09:01:35.346599+01:00 php-fpm 44701 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. 2025-05-29 09:01:34.234855+01:00 rtsold 48296 Received RA specifying route fe80::xxxx:feed:xxxx:b100 for interface wan(pppoe0) 2025-05-29 09:01:33.551216+01:00 avahi-daemon 31475 Joining mDNS multicast group on interface ice0.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:33.551169+01:00 avahi-daemon 31475 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:33.550851+01:00 avahi-daemon 31475 Joining mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:33.550799+01:00 avahi-daemon 31475 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:32.170045+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:32.163065+01:00 php-fpm 53259 /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. 2025-05-29 09:01:32.162769+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:27.243803+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:27.218513+01:00 check_reload_status 678 updating dyndns opt3 2025-05-29 09:01:26.122444+01:00 php-fpm 44701 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' 2025-05-29 09:01:25.267464+01:00 kernel - cannot forward src fe80::6:xxxx:xxxx:xxxx:xxxx:2eba, dst 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc, nxt 58, rcvif ice0, outif pppoe0 2025-05-29 09:01:25.080788+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:25.080721+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:25.043749+01:00 check_reload_status 678 updating dyndns opt1 2025-05-29 09:01:24.262389+01:00 kernel - cannot forward src fe80::6:xxxx:xxxx:xxxx:xxxx:2eba, dst 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc, nxt 58, rcvif ice0, outif pppoe0 2025-05-29 09:01:23.963952+01:00 php-fpm 49275 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' 2025-05-29 09:01:23.494001+01:00 php-fpm 44701 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1748505683] unbound[76538:0] error: bind: address already in use [1748505683] unbound[76538:0] fatal error: could not open ports' 2025-05-29 09:01:23.257473+01:00 kernel - cannot forward src fe80::6:xxxx:xxxx:xxxx:xxxx:2eba, dst 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc, nxt 58, rcvif ice0, outif pppoe0 2025-05-29 09:01:21.899908+01:00 check_reload_status 678 Restarting IPsec tunnels 2025-05-29 09:01:21.850491+01:00 kernel - ice0: Media change is not supported. 2025-05-29 09:01:21.834135+01:00 avahi-daemon 31475 New relevant interface ice0.IPv4 for mDNS. 2025-05-29 09:01:21.833754+01:00 avahi-daemon 31475 Joining mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. 2025-05-29 09:01:21.832940+01:00 php-fpm 44701 /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' 2025-05-29 09:01:21.822119+01:00 avahi-daemon 31475 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:21.822082+01:00 avahi-daemon 31475 Leaving mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. 2025-05-29 09:01:21.818647+01:00 avahi-daemon 31475 Interface ice0.IPv4 no longer relevant for mDNS. 2025-05-29 09:01:21.818421+01:00 avahi-daemon 31475 Leaving mDNS multicast group on interface ice0.IPv4 with address 10.0.1.1. 2025-05-29 09:01:21.818044+01:00 php-fpm 44701 /rc.linkup: HOTPLUG: Configuring interface opt3 2025-05-29 09:01:21.818030+01:00 php-fpm 44701 /rc.linkup: DEVD Ethernet attached event for opt3 2025-05-29 09:01:21.817969+01:00 php-fpm 44701 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) 2025-05-29 09:01:21.817426+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:21.404780+01:00 php-fpm 53259 /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1748505681] unbound[10766:0] error: bind: address already in use [1748505681] unbound[10766:0] fatal error: could not open ports' 2025-05-29 09:01:20.722236+01:00 php-fpm 4025 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' 2025-05-29 09:01:19.834473+01:00 kernel - ice0: Media change is not supported. 2025-05-29 09:01:19.768524+01:00 php-fpm 53259 /rc.newwanipv6: rc.newwanipv6: on (IP address: 2a02:xxxx:feed:xxxx:xxxx:xxxx:xxxx:e706) (interface: wan) (real interface: pppoe0). 2025-05-29 09:01:19.766297+01:00 php-fpm 53259 /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. 2025-05-29 09:01:19.750195+01:00 check_reload_status 678 Restarting IPsec tunnels 2025-05-29 09:01:19.700955+01:00 avahi-daemon 31475 Joining mDNS multicast group on interface ice0.IPv6 with address fe80::1:1. 2025-05-29 09:01:19.700910+01:00 avahi-daemon 31475 Leaving mDNS multicast group on interface ice0.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:19.683175+01:00 avahi-daemon 31475 New relevant interface ice0.1003.IPv4 for mDNS. 2025-05-29 09:01:19.683067+01:00 avahi-daemon 31475 Joining mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. 2025-05-29 09:01:19.681551+01:00 php-fpm 49275 /rc.linkup: The command '/sbin/ifconfig 'ice0' media 'autoselect'' returned exit code '1', the output was 'ifconfig: SIOCSIFMEDIA (media): Operation not supported by device' 2025-05-29 09:01:19.668583+01:00 avahi-daemon 31475 Joining mDNS multicast group on interface ice0.1003.IPv6 with address fe80::xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:19.668537+01:00 avahi-daemon 31475 Leaving mDNS multicast group on interface ice0.1003.IPv6 with address 2a02:xxx:xxxx:x:xxxx:xxxx:xxxx:ebdc. 2025-05-29 09:01:19.643980+01:00 avahi-daemon 31475 Interface ice0.1003.IPv4 no longer relevant for mDNS. 2025-05-29 09:01:19.643909+01:00 avahi-daemon 31475 Leaving mDNS multicast group on interface ice0.1003.IPv4 with address 172.16.1.1. 2025-05-29 09:01:19.643501+01:00 php-fpm 49275 /rc.linkup: HOTPLUG: Configuring interface opt1 2025-05-29 09:01:19.643485+01:00 php-fpm 49275 /rc.linkup: DEVD Ethernet attached event for opt1 2025-05-29 09:01:19.643425+01:00 php-fpm 49275 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) 2025-05-29 09:01:19.642999+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:19.642929+01:00 check_reload_status 678 Reloading filter 2025-05-29 09:01:18.511522+01:00 php-fpm 58359 /rc.linkup: The command '/usr/sbin/arp -s '192.168.1.1' '3c:xx:xx:xx:xx:22'' returned exit code '1', the output was 'arp: set 192.168.1.1: Operation not permitted' 2025-05-29 09:01:17.408487+01:00 php-fpm 58359 /rc.linkup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1748505677] unbound[33040:0] error: bind: address already in use [1748505677] unbound[33040:0] fatal error: could not open ports' 2025-05-29 09:01:15.751639+01:00 php-fpm 58359 /rc.linkup: DEVD Ethernet detached event for opt1 2025-05-29 09:01:15.751377+01:00 php-fpm 58359 /rc.linkup: Hotplug event detected for VLAN(opt1) dynamic IP address (4: 172.16.1.1, 6: track6) 2025-05-29 09:01:15.745652+01:00 php-fpm 4025 /rc.linkup: DEVD Ethernet detached event for opt3 2025-05-29 09:01:15.745594+01:00 php-fpm 4025 /rc.linkup: Hotplug event detected for LAN(opt3) dynamic IP address (4: 10.0.1.1, 6: track6) 2025-05-29 09:01:14.809572+01:00 kernel - ice0.1003: link state changed to UP 2025-05-29 09:01:14.809554+01:00 kernel - ice0: link state changed to UP 2025-05-29 09:01:14.809533+01:00 kernel - ice0: Link is up, 10 Gbps Full Duplex, Requested FEC: None, Negotiated FEC: None, Autoneg: False, Flow Control: None 2025-05-29 09:01:14.809512+01:00 kernel - ice0.1003: link state changed to DOWN 2025-05-29 09:01:14.809480+01:00 kernel - ice0: link state changed to DOWN 2025-05-29 09:01:14.788843+01:00 check_reload_status 678 Linkup starting ice0.1003 2025-05-29 09:01:14.783970+01:00 check_reload_status 678 Linkup starting ice0 2025-05-29 09:01:14.697977+01:00 check_reload_status 678 Linkup starting ice0.1003 2025-05-29 09:01:14.692890+01:00 check_reload_status 678 Linkup starting ice0 2025-05-29 07:15:24.760448+01:00 php_pfb 12603 [pfBlockerNG] filterlog daemon started
The rough periodicity of just after a 15/30/45/00 minute mark or just after pfSense or services are doing something is still there, as is the
check_reload_status
command as an apparent trigger event. As to what is triggering thecheck_reload_status
is unclear.️
-
I think the ordering there is confusing. check_reload_status is triggered by the NIC state change event, I'm not sure why it is logged first but that's not uncommon to see.
Everything else is just the fallout from that.
At this point it does look unrelated to if_pppoe though would you agree?