Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    DNS resolver exiting when loading pfblocker 25.03.b.20250409.2208

    Scheduled Pinned Locked Moved Plus 25.03 Develoment Snapshots
    49 Posts 3 Posters 1.6k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • stephenw10S
      stephenw10 Netgate Administrator
      last edited by

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

      RobbieTTR 1 Reply Last reply Reply Quote 0
      • RobbieTTR
        RobbieTT @stephenw10
        last edited by RobbieTT

        @stephenw10

        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.

        ☕️

        1 Reply Last reply Reply Quote 0
        • stephenw10S
          stephenw10 Netgate Administrator
          last edited by stephenw10

          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 ice0

          Can you try a different port there?

          Weird that the switch doesn't show it though...

          RobbieTTR 1 Reply Last reply Reply Quote 0
          • RobbieTTR
            RobbieTT @stephenw10
            last edited by

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

            ☕️

            w0wW 1 Reply Last reply Reply Quote 0
            • w0wW
              w0w @RobbieTT
              last edited by w0w

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

              1 Reply Last reply Reply Quote 0
              • stephenw10S
                stephenw10 Netgate Administrator
                last edited by

                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.

                RobbieTTR 1 Reply Last reply Reply Quote 0
                • RobbieTTR
                  RobbieTT @stephenw10
                  last edited by RobbieTT

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

                  #14431

                  ☕️

                  1 Reply Last reply Reply Quote 0
                  • stephenw10S
                    stephenw10 Netgate Administrator
                    last edited by

                    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.

                    RobbieTTR 2 Replies Last reply Reply Quote 0
                    • RobbieTTR
                      RobbieTT @stephenw10
                      last edited by RobbieTT

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

                      ☕️

                      1 Reply Last reply Reply Quote 0
                      • stephenw10S
                        stephenw10 Netgate Administrator
                        last edited by

                        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.

                        RobbieTTR 3 Replies Last reply Reply Quote 0
                        • RobbieTTR
                          RobbieTT @stephenw10
                          last edited by

                          @stephenw10

                          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.

                          ☕️

                          1 Reply Last reply Reply Quote 0
                          • RobbieTTR
                            RobbieTT @stephenw10
                            last edited by

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

                            ☕️

                            1 Reply Last reply Reply Quote 0
                            • RobbieTTR
                              RobbieTT @stephenw10
                              last edited by RobbieTT

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

                              ☕️

                              1 Reply Last reply Reply Quote 0
                              • RobbieTTR
                                RobbieTT @stephenw10
                                last edited by

                                @stephenw10

                                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.

                                ☕️

                                1 Reply Last reply Reply Quote 0
                                • stephenw10S
                                  stephenw10 Netgate Administrator
                                  last edited by

                                  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.

                                  RobbieTTR 1 Reply Last reply Reply Quote 0
                                  • RobbieTTR
                                    RobbieTT @stephenw10
                                    last edited by

                                    @stephenw10

                                    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?

                                    ☕️

                                    w0wW 1 Reply Last reply Reply Quote 0
                                    • stephenw10S
                                      stephenw10 Netgate Administrator
                                      last edited by

                                      Hmm, gotta be some driver difference.

                                      Are you using the ice_dpp module?

                                      RobbieTTR 2 Replies Last reply Reply Quote 0
                                      • w0wW
                                        w0w @RobbieTT
                                        last edited by w0w

                                        @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

                                        2cea7c79-bf35-43f2-98ca-24d74f2fbc77-image.png

                                        RobbieTTR 1 Reply Last reply Reply Quote 2
                                        • RobbieTTR
                                          RobbieTT @stephenw10
                                          last edited by RobbieTT

                                          @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

                                          ☕️

                                          1 Reply Last reply Reply Quote 0
                                          • RobbieTTR
                                            RobbieTT @w0w
                                            last edited by

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

                                            ☕️

                                            1 Reply Last reply Reply Quote 0
                                            • First post
                                              Last post
                                            Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.