DNS/DHCP stop working suddenly

[tinfoilmatt]

@michmoor five minutes doesn't seem reasonable given documented precaution:

https://docs.netgate.com/pfsense/en/latest/diagnostics/system-halt.html

...and what you seemed to be dealing with more specifically.

abrupt and repeated power losses over time might be closer in line with your 'root cause' than any particular package. i personally think it'd be advisable to make not cutting the power until you've waited at least an unreasonable period of time given the specific reboot context (sysem updates, maintenance, system crash, etc.) a more regular practice.

pfSense is a software firewall that doesn't load its config strictly out of NVRAM like typical consumer devices often do. despite filesystem and backup/recovery/snapshot improvements over time, OS corruption is still a real concern with abrupt loss of system power.

[stephenw10]

In reality I don't think I've ever seen a correctly functioning install take more than 5 mins to shutdown.

[tinfoilmatt]

@stephenw10 said in DNS/DHCP stop working suddenly:

In reality I don't think I've ever seen a correctly functioning install take more than 5 mins to shutdown.

so you would pull the physical power after five minutes of Stopping package Tailscale... in some kind of unstable system state?

[stephenw10]

If the console was hung at that point then yes. I might try hitting ctl+t first to see what it's actually waiting for. That won't allow it to continue but might give a clue as to why it failed.

[tinfoilmatt]

@stephenw10 said in DNS/DHCP stop working suddenly:

If the console was hung at that point then yes. I might try hitting ctl+t first to see what it's actually waiting for. That won't allow it to continue but might give a clue as to why it failed.

lol

[michmoor]

@stephenw10
Hey Stephen,
It happened again. I collected some data to help diagnose

I initially SSH'd to my firewall and was able to run a top -aSH.

last pid: 37748;  load averages:  5.19,  5.30,  5.34                                                                                                         up 5+14:27:25  06:36:49
536 threads:   10 running, 488 sleeping, 38 waiting
CPU:  1.1% user,  0.0% nice, 26.6% system,  0.1% interrupt, 72.3% idle
Mem: 471M Active, 1981M Inact, 1400M Wired, 3937M Free
ARC: 341M Total, 106M MFU, 214M MRU, 2972K Anon, 2640K Header, 14M Other
     267M Compressed, 972M Uncompressed, 3.64:1 Ratio
Swap: 1024M Total, 1024M Free

  PID USERNAME    PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
    0 root        -60    -     0B  2160K CPU3     3 260:17  99.91% [kernel{if_io_tqg_3}]
   11 root        187 ki31     0B    64K CPU0     0 127.5H  96.51% [idle{idle: cpu0}]
   11 root        187 ki31     0B    64K CPU1     1 126.0H  95.49% [idle{idle: cpu1}]
   11 root        187 ki31     0B    64K RUN      2 126.7H  95.47% [idle{idle: cpu2}]
98424 unbound      23    0   179M   139M kqread   1   0:06   3.65% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
98424 unbound      21    0   179M   139M kqread   2   0:05   2.39% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}

I noticed that my WAN IP has changed. Being on ATT fiber it has remained the same for over two years but its DHCP so now its time to change.

All logging stopped at the same time

-rw-------  1 root       wheel       572K Mar  7 02:29 filter.log.1.bz2
-rw-------  1 root       wheel       534K Mar  7 02:35 filter.log.0.bz2
-rw-------  1 root       wheel       214K Mar  7 02:37 resolver.log.1.bz2
-rw-------  1 root       wheel       149K Mar  7 02:39 resolver.log.0.bz2
-rw-------  1 root       wheel       2.9M Mar  7 02:39 auth.log
-rw-------  1 root       wheel       938K Mar  7 02:39 dhcpd.log
-rw-------  1 root       wheel       3.1M Mar  7 02:39 gateways.log
-rw-------  1 root       wheel       544K Mar  7 02:39 ntpd.log
-rw-------  1 root       wheel       2.6M Mar  7 02:39 nginx.log
-rw-------  1 root       wheel       2.8M Mar  7 02:39 routing.log
-rw-------  1 root       wheel       2.5M Mar  7 02:39 ipsec.log
-rw-------  1 root       wheel       2.5M Mar  7 02:39 openvpn.log
-rw-------  1 root       wheel       6.5M Mar  7 02:39 system.log
-rw-------  1 root       wheel       8.4M Mar  7 02:39 filter.log
-rw-------  1 root       wheel       426K Mar  7 02:39 resolver.log
-rw-------  1 freeradius freeradius  879K Mar  7 02:40 radius.log
-rw-r--r--  1 root       wheel       591B Mar  7 06:36 utx.lastlogin
-rw-------  1 root       wheel        22K Mar  7 06:36 utx.log

I still couldn't get to the GUI on the LAN side as it was unresponsive so from SSH I went ahead with the reboot. It was stalling on stopping certain packages so I did ctrl t

Netgate pfSense Plus is rebooting now.
 Stopping package arpwatch...done.
 Stopping package freeradius3...done.
 Stopping package lldpd...done.
 Stopping package WireGuard...
load: 5.71  cmd: php_wg 65403 [nanslp] 10.49r 0.68u 0.07s 3% 53036k
done.
 Stopping package haproxy...done.
 Stopping package nut...done.
 Stopping package syslog-ng...done.
 Stopping package softflowd...done.
 Stopping package suricata...

 Stopping package suricata...
load: 5.59  cmd: php-cgi 56784 [nanslp] 35.07r 0.54u 0.04s 0% 53360k

Waiting over an hour...........yes an hour...pfsense never came back from the reboot and within that hour I lost access to the shell. So I went in through the console and the console was flooded with the following logs.

arpresolve: can't allocate llinfo for 192.168.1.254 on ix3

I couldn't access anything else via console. Just the flooding of the arpresolve log tied up anything. Even disconnecting the ix3 interface from the ATT modem didn't matter..arpresolve still kept flooding console.

Finally, a reboot fixed it. Back online..

[tinfoilmatt]

@michmoor sounds like a simple gateway alarm/action triggering a cascade of headache. you might review configuration of the packages whose services you're not allowing to stop, likely compounding the kludge each time you do. it'll only get longer and kludgier if you keep "resolving" it the way you are.

Suricata initialization (both start and stop) is what's causing those arpresolve kernel notices.

[stephenw10]

Do you have the service watchdog installed? That can cause problems with stopping services when incorrectly used. It should only really be used for debugging. You would see that logged though.

[michmoor]

@stephenw10
When @cyberconsultants mentioned suricata i did immediately go to my service watchdog and I have the following enabled.

This is a set up Ive had for years now. I don't mind removing these services from monitoring but i don't see how it prevented a reboot. Ive upgraded/rebooted many times with these enabled.

edit: I would also say that its likely something environmentally changed here but I have no idea what it could be. Short of adding a firewall rule, the config is static. Goes down for an upgrade every few months. So whatever is causing a cascade of headaches for me (love the term) its proving difficult to isolate.

[stephenw10]

Well the service watchdog should log if it restarts anything so I'd expect to see that in the system logs. Unless it's not logging anything of course.

It's an easy test to remove those though. Unbound is the only thing I could imagine being an issue though.

[NollipfSense]

Very interesting diagnosing here, indeed and Steve is bad to the bone!

[stephenw10]

Not sure about that. Come back to me if/when we find the root cause.

[tinfoilmatt]

@stephenw10 it's pretty obviously, based on OP's detailed posts and a fair bit of 'reading between the lines,' triggered gateway monitoring action following either transiest latency/loss of connecitivty or DHCP lease renewal.

the rest of it is just system tailspin—which in fairness would, in all likelihood, eventually recover given enough time to do so. BSD and pfSense be solid like that.

[stephenw10]

Yes, exactly I don't expect to just get hung up in the interface/network like that. You certainly can end up with a lot of script 'churn' when an interface drops out. Especially if there are other interfaces on it like VPNs etc. But it will stop after a few minutes unless the interface changes again.

[bmeeks]

@michmoor said in DNS/DHCP stop working suddenly:

@stephenw10
When @cyberconsultants mentioned suricata i did immediately go to my service watchdog and I have the following enabled.

This is a set up Ive had for years now. I don't mind removing these services from monitoring but i don't see how it prevented a reboot. Ive upgraded/rebooted many times with these enabled.

edit: I would also say that its likely something environmentally changed here but I have no idea what it could be. Short of adding a firewall rule, the config is static. Goes down for an upgrade every few months. So whatever is causing a cascade of headaches for me (love the term) its proving difficult to isolate.

One of the issues with Service Watchdog is that the package is not super smart. It simply looks for the presence or absence of the monitored daemon, and sends it a start command if missing. Lots of things can result in normal restarts of certain daemons -- unbound being one of those daemons. Consider this scenario:

unbound can be normally restarted by several things:

1. If you have DHCP hostname registration enabled (most don't, but if you do) it will restart unbound each time a DHCP lease renews. But Service Watchdog is not aware of that. It will simply blindly see unbound not running at the instant it checks and then send it a restart command without knowing the service is already in the middle of restarting.

2. A temporary issue with your WAN (packet loss, for example) might trigger a gateway alarm. If that deteriorates into a down condition, pfSense will issue a command to restart a bunch of processes including unbound. Again, Service Watchdog is ignorant of this process. It will see unbound missing from the list of running daemons when it spot checks, and thus issue a restart command. But pfSense itself is already restarting unbound. That can lead to problems.

3. If you run pfBlockerNG, it can also issue restart commands to unbound in some update scenarios. Service Watchdog is ignorant of this process as well, and will just blindly issue a restart command when it fails to see a running unbound daemon.

So, looking at the scenarios above you can see that it would be possible for bad things to happen if two unbound instances are trying to both start simultaneously. And whether or not this might occur would be random as it would depend on the exact timing differences between the natural restart process and when Service Watchdog sends it own independent restart signal.

As @stephenw10 mentioned, Service Watchdog is really only intended for use when debugging a problem or working around some known issue. It is not a great solution for routine monitoring - especially monitoring of processes that can be restarted for legitimate reasons. This is why I preach to never use it with the IDS/IPS packages. Service Watchdog just does not consider if a service is legitimately restarting and thus the missing daemon instance is expected (and to be fair, it can't know this). It just says "no daemon present at this instant, so restart!".

[michmoor]

@cyberconsultants @stephenw10

Well lets dissect this a bit then. As far as Gateway actions are concerned its disabled. Has been for a while

So if the trigger is my WAN address releasing/renewing an address why all of a sudden?

Based on the alerts from monitoring this problem started at 12:47am ET. Lets review what i could dig up in graylog.

Ping monitors to my WAN address also fail at this time. So the WAN address was not accessible.

During this time the filterlog still shows traffic inbound to my old IP so i am inferring that traffic was still making it into the firewall. In fact traffic continues to come inbound until 2:47:58am ET where there is a dhclient process starting which of course is the DHCP call out on the WAN.

The link flaps a few times

Thats when things crap the bed and no more inbound flows

timestamp	source	message
2024-03-07T01:01:00.000-05:00	php-cgi[67141]:	php-cgi[67141]: rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:36:45.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:36:45.000-05:00	kernel:	kernel: ix3: link state changed to DOWN
2024-03-07T02:36:45.000-05:00	GAFW	GAFW dhclient[32095]: ix3 link state up -> down
2024-03-07T02:36:47.000-05:00	charon[71782]:	charon[71782]: 06[KNL] 162.193.210.96 disappeared from ix3
2024-03-07T02:36:47.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Failed to get IP for interface ix3
2024-03-07T02:36:47.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Cannot get IP address for ext interface ix3. Network is down
2024-03-07T02:36:49.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:36:49.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:36:53.000-05:00	ntpd[86868]:	ntpd[86868]: Deleting interface #55 ix3, 162.193.210.96#123, interface stats: received=1173, sent=1257, dropped=0, active_time=127360 secs
2024-03-07T02:36:55.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:36:55.000-05:00	kernel:	kernel: ix3: link state changed to UP
2024-03-07T02:36:56.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:36:57.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:36:58.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:36:59.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:01.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:05.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:09.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:37:10.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:37:11.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 2
2024-03-07T02:37:13.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 4
2024-03-07T02:37:17.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 6
2024-03-07T02:37:23.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 8
2024-03-07T02:37:26.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:26.000-05:00	kernel:	kernel: ix3: link state changed to DOWN
2024-03-07T02:37:26.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state up -> down
2024-03-07T02:37:31.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 15
2024-03-07T02:37:46.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 10
2024-03-07T02:37:50.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:50.000-05:00	kernel:	kernel: ix3: link state changed to UP
2024-03-07T02:37:50.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:50.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state down -> up
2024-03-07T02:37:52.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:56.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:56.000-05:00	kernel:	kernel: ix3: link state changed to DOWN
2024-03-07T02:37:56.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:56.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 10
2024-03-07T02:37:56.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state up -> down
2024-03-07T02:37:58.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:58.000-05:00	kernel:	kernel: ix3: link state changed to UP
2024-03-07T02:37:58.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:58.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state down -> up
2024-03-07T02:37:59.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:00.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:01.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:03.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:06.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:06.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 7
2024-03-07T02:38:13.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 9
2024-03-07T02:38:17.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:38:18.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:38:19.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:38:20.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 2
2024-03-07T02:38:22.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 2
2024-03-07T02:38:24.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 3
2024-03-07T02:38:26.000-05:00	check_reload_status[460]:	check_reload_status[460]: rc.newwanip starting ix3
2024-03-07T02:38:26.000-05:00	charon[71782]:	charon[71782]: 01[KNL] 192.168.1.94 appeared on ix3
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[89711]: /sbin/route add -host 192.168.1.254 -iface ix3
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[87947]: Adding new routes to interface: ix3
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[87082]: New Routers (ix3): 192.168.1.254
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[86571]: New Broadcast Address (ix3): 192.168.1.255
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[85955]: New Subnet Mask (ix3): 255.255.255.0
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[85320]: New IP Address (ix3): 192.168.1.94
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[84415]: ifconfig ix3 inet 192.168.1.94 netmask 255.255.255.0 broadcast 192.168.1.255
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:27.000-05:00	php-fpm[44338]:	php-fpm[44338]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.94) (interface: WAN[wan]) (real interface: ix3).
2024-03-07T02:38:27.000-05:00	php-fpm[44338]:	php-fpm[44338]: /rc.newwanip: rc.newwanip: Info: starting on ix3.
2024-03-07T02:38:29.000-05:00	ntpd[86868]:	ntpd[86868]: Listen normally on 58 ix3 192.168.1.94:123
2024-03-07T02:38:31.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Failed to get IP for interface ix3
2024-03-07T02:38:31.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Cannot get IP address for ext interface ix3. Network is down
2024-03-07T02:38:31.000-05:00	charon[71782]:	charon[71782]: 01[KNL] 192.168.1.94 disappeared from ix3
2024-03-07T02:38:34.000-05:00	ntpd[86868]:	ntpd[86868]: Deleting interface #58 ix3, 192.168.1.94#123, interface stats: received=0, sent=0, dropped=4, active_time=5 secs
2024-03-07T02:38:34.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:34.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:35.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:35.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:36.000-05:00	check_reload_status[460]:	check_reload_status[460]: rc.newwanip starting ix3
2024-03-07T02:38:36.000-05:00	charon[71782]:	charon[71782]: 01[KNL] 192.168.1.94 appeared on ix3
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[42980]: /sbin/route add -host 192.168.1.254 -iface ix3
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[40764]: Adding new routes to interface: ix3
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[39766]: New Routers (ix3): 192.168.1.254
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[38095]: New Broadcast Address (ix3): 192.168.1.255
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[37026]: New Subnet Mask (ix3): 255.255.255.0
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[35894]: New IP Address (ix3): 192.168.1.94
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[34295]: ifconfig ix3 inet 192.168.1.94 netmask 255.255.255.0 broadcast 192.168.1.255
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[28646]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:37.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.94) (interface: WAN[wan]) (real interface: ix3).
2024-03-07T02:38:37.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.newwanip: rc.newwanip: Info: starting on ix3.
2024-03-07T02:38:39.000-05:00	ntpd[86868]:	ntpd[86868]: Listen normally on 59 ix3 192.168.1.94:123
2024-03-07T02:38:41.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Failed to get IP for interface ix3
2024-03-07T02:38:41.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Cannot get IP address for ext interface ix3. Network is down
2024-03-07T02:38:41.000-05:00	charon[71782]:	charon[71782]: 08[KNL] 192.168.1.94 disappeared from ix3
2024-03-07T02:38:44.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:44.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:44.000-05:00	ntpd[86868]:	ntpd[86868]: Deleting interface #59 ix3, 192.168.1.94#123, interface stats: received=0, sent=0, dropped=4, active_time=5 secs
2024-03-07T02:38:45.000-05:00	check_reload_status[460]:	check_reload_status[460]: rc.newwanip starting ix3
2024-03-07T02:38:45.000-05:00	charon[71782]:	charon[71782]: 10[KNL] 192.168.1.94 appeared on ix3
2024-03-07T02:38:45.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:45.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[25149]: /sbin/route add -host 192.168.1.254 -iface ix3
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[23218]: Adding new routes to interface: ix3
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[22332]: New Routers (ix3): 192.168.1.254
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[20657]: New Broadcast Address (ix3): 192.168.1.255
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[19212]: New Subnet Mask (ix3): 255.255.255.0
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[17977]: New IP Address (ix3): 192.168.1.94
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[15786]: ifconfig ix3 inet 192.168.1.94 netmask 255.255.255.0 broadcast 192.168.1.255
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[8968]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:46.000-05:00	php-fpm[19319]:	php-fpm[19319]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.94) (interface: WAN[wan]) (real interface: ix3).
2024-03-07T02:38:46.000-05:00	php-fpm[19319]:	php-fpm[19319]: /rc.newwanip: rc.newwanip: Info: starting on ix3.
2024-03-07T02:38:48.000-05:00	ntpd[86868]:	ntpd[86868]: Listen normally on 60 ix3 192.168.1.94:123
2024-03-07T02:38:57.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:57.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:58.000-05:00	php-fpm[44338]:	php-fpm[44338]: /rc.newwanip: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:39:00.000-05:00	GAFW	GAFW dhclient[8968]: DHCPREQUEST on ix3 to 192.168.1.254 port 67

[michmoor]

Its highly likely that multiple scenrios are happening that are negatively impacting.
Watchdog is no longer monitoring any service

Its probable that something did occur that caused the firewall to be inaccessible from the LAN side and may be related to the watchdog process and restarting unbound. Suricata was never part of the watchdog daemon monitoring.

That said, i will just have to wait to see if this happens again.
I appreciate everyone chiming in on this one.

[tinfoilmatt]

@michmoor said in DNS/DHCP stop working suddenly:

Based on the alerts from monitoring this problem started at 12:47am ET. Lets review what i could dig up in graylog.

Ping monitors to my WAN address also fail at this time. So the WAN address was not accessible.

During this time the filterlog still shows traffic inbound to my old IP so i am inferring that traffic was still making it into the firewall. In fact traffic continues to come inbound until 2:47:58am ET where there is a dhclient process starting which of course is the DHCP call out on the WAN.

The link flaps a few times

Thats when things crap the bed and no more inbound flows

timestamp	source	message
2024-03-07T01:01:00.000-05:00	php-cgi[67141]:	php-cgi[67141]: rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:36:45.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:36:45.000-05:00	kernel:	kernel: ix3: link state changed to DOWN
2024-03-07T02:36:45.000-05:00	GAFW	GAFW dhclient[32095]: ix3 link state up -> down
2024-03-07T02:36:47.000-05:00	charon[71782]:	charon[71782]: 06[KNL] 162.193.210.96 disappeared from ix3
2024-03-07T02:36:47.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Failed to get IP for interface ix3
2024-03-07T02:36:47.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Cannot get IP address for ext interface ix3. Network is down
2024-03-07T02:36:49.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:36:49.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:36:53.000-05:00	ntpd[86868]:	ntpd[86868]: Deleting interface #55 ix3, 162.193.210.96#123, interface stats: received=1173, sent=1257, dropped=0, active_time=127360 secs
2024-03-07T02:36:55.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:36:55.000-05:00	kernel:	kernel: ix3: link state changed to UP
2024-03-07T02:36:56.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:36:57.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:36:58.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:36:59.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:01.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:05.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:09.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:37:10.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:37:11.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 2
2024-03-07T02:37:13.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 4
2024-03-07T02:37:17.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 6
2024-03-07T02:37:23.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 8
2024-03-07T02:37:26.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:26.000-05:00	kernel:	kernel: ix3: link state changed to DOWN
2024-03-07T02:37:26.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state up -> down
2024-03-07T02:37:31.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 15
2024-03-07T02:37:46.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 10
2024-03-07T02:37:50.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:50.000-05:00	kernel:	kernel: ix3: link state changed to UP
2024-03-07T02:37:50.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:50.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state down -> up
2024-03-07T02:37:52.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:56.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:56.000-05:00	kernel:	kernel: ix3: link state changed to DOWN
2024-03-07T02:37:56.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:56.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 10
2024-03-07T02:37:56.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state up -> down
2024-03-07T02:37:58.000-05:00	check_reload_status[460]:	check_reload_status[460]: Linkup starting ix3
2024-03-07T02:37:58.000-05:00	kernel:	kernel: ix3: link state changed to UP
2024-03-07T02:37:58.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:37:58.000-05:00	GAFW	GAFW dhclient[14415]: ix3 link state down -> up
2024-03-07T02:37:59.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:00.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:01.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:03.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:06.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:06.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 7
2024-03-07T02:38:13.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 9
2024-03-07T02:38:17.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:38:18.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:38:19.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 1
2024-03-07T02:38:20.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 2
2024-03-07T02:38:22.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 2
2024-03-07T02:38:24.000-05:00	GAFW	GAFW dhclient[14415]: DHCPDISCOVER on ix3 to 255.255.255.255 port 67 interval 3
2024-03-07T02:38:26.000-05:00	check_reload_status[460]:	check_reload_status[460]: rc.newwanip starting ix3
2024-03-07T02:38:26.000-05:00	charon[71782]:	charon[71782]: 01[KNL] 192.168.1.94 appeared on ix3
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[89711]: /sbin/route add -host 192.168.1.254 -iface ix3
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[87947]: Adding new routes to interface: ix3
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[87082]: New Routers (ix3): 192.168.1.254
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[86571]: New Broadcast Address (ix3): 192.168.1.255
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[85955]: New Subnet Mask (ix3): 255.255.255.0
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[85320]: New IP Address (ix3): 192.168.1.94
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[84415]: ifconfig ix3 inet 192.168.1.94 netmask 255.255.255.0 broadcast 192.168.1.255
2024-03-07T02:38:26.000-05:00	GAFW	GAFW dhclient[14415]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:27.000-05:00	php-fpm[44338]:	php-fpm[44338]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.94) (interface: WAN[wan]) (real interface: ix3).
2024-03-07T02:38:27.000-05:00	php-fpm[44338]:	php-fpm[44338]: /rc.newwanip: rc.newwanip: Info: starting on ix3.
2024-03-07T02:38:29.000-05:00	ntpd[86868]:	ntpd[86868]: Listen normally on 58 ix3 192.168.1.94:123
2024-03-07T02:38:31.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Failed to get IP for interface ix3
2024-03-07T02:38:31.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Cannot get IP address for ext interface ix3. Network is down
2024-03-07T02:38:31.000-05:00	charon[71782]:	charon[71782]: 01[KNL] 192.168.1.94 disappeared from ix3
2024-03-07T02:38:34.000-05:00	ntpd[86868]:	ntpd[86868]: Deleting interface #58 ix3, 192.168.1.94#123, interface stats: received=0, sent=0, dropped=4, active_time=5 secs
2024-03-07T02:38:34.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:34.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:35.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:35.000-05:00	php-fpm[78999]:	php-fpm[78999]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:36.000-05:00	check_reload_status[460]:	check_reload_status[460]: rc.newwanip starting ix3
2024-03-07T02:38:36.000-05:00	charon[71782]:	charon[71782]: 01[KNL] 192.168.1.94 appeared on ix3
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[42980]: /sbin/route add -host 192.168.1.254 -iface ix3
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[40764]: Adding new routes to interface: ix3
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[39766]: New Routers (ix3): 192.168.1.254
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[38095]: New Broadcast Address (ix3): 192.168.1.255
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[37026]: New Subnet Mask (ix3): 255.255.255.0
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[35894]: New IP Address (ix3): 192.168.1.94
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[34295]: ifconfig ix3 inet 192.168.1.94 netmask 255.255.255.0 broadcast 192.168.1.255
2024-03-07T02:38:36.000-05:00	GAFW	GAFW dhclient[28646]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:37.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.94) (interface: WAN[wan]) (real interface: ix3).
2024-03-07T02:38:37.000-05:00	php-fpm[5633]:	php-fpm[5633]: /rc.newwanip: rc.newwanip: Info: starting on ix3.
2024-03-07T02:38:39.000-05:00	ntpd[86868]:	ntpd[86868]: Listen normally on 59 ix3 192.168.1.94:123
2024-03-07T02:38:41.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Failed to get IP for interface ix3
2024-03-07T02:38:41.000-05:00	miniupnpd[92455]:	miniupnpd[92455]: Cannot get IP address for ext interface ix3. Network is down
2024-03-07T02:38:41.000-05:00	charon[71782]:	charon[71782]: 08[KNL] 192.168.1.94 disappeared from ix3
2024-03-07T02:38:44.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:44.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:44.000-05:00	ntpd[86868]:	ntpd[86868]: Deleting interface #59 ix3, 192.168.1.94#123, interface stats: received=0, sent=0, dropped=4, active_time=5 secs
2024-03-07T02:38:45.000-05:00	check_reload_status[460]:	check_reload_status[460]: rc.newwanip starting ix3
2024-03-07T02:38:45.000-05:00	charon[71782]:	charon[71782]: 10[KNL] 192.168.1.94 appeared on ix3
2024-03-07T02:38:45.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:45.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[25149]: /sbin/route add -host 192.168.1.254 -iface ix3
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[23218]: Adding new routes to interface: ix3
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[22332]: New Routers (ix3): 192.168.1.254
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[20657]: New Broadcast Address (ix3): 192.168.1.255
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[19212]: New Subnet Mask (ix3): 255.255.255.0
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[17977]: New IP Address (ix3): 192.168.1.94
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[15786]: ifconfig ix3 inet 192.168.1.94 netmask 255.255.255.0 broadcast 192.168.1.255
2024-03-07T02:38:45.000-05:00	GAFW	GAFW dhclient[8968]: DHCPREQUEST on ix3 to 255.255.255.255 port 67
2024-03-07T02:38:46.000-05:00	php-fpm[19319]:	php-fpm[19319]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.94) (interface: WAN[wan]) (real interface: ix3).
2024-03-07T02:38:46.000-05:00	php-fpm[19319]:	php-fpm[19319]: /rc.newwanip: rc.newwanip: Info: starting on ix3.
2024-03-07T02:38:48.000-05:00	ntpd[86868]:	ntpd[86868]: Listen normally on 60 ix3 192.168.1.94:123
2024-03-07T02:38:57.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com) There was an error trying to determine the public IP for interface - wan (ix3 ).
2024-03-07T02:38:57.000-05:00	php-fpm[93379]:	php-fpm[93379]: /rc.dyndns.update: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:38:58.000-05:00	php-fpm[44338]:	php-fpm[44338]: /rc.newwanip: Dynamic DNS (vpn.networkingtitan.com): running get_failover_interface for wan. found ix3
2024-03-07T02:39:00.000-05:00	GAFW	GAFW dhclient[8968]: DHCPREQUEST on ix3 to 192.168.1.254 port 67

based on some of that timestamping and behavior, ISP maintenance seems within the realm of possibilites, too (if you haven't already confirmed or not with them).

again, it's the outage that casues the cascade of restarts/retries/timeout-counters counting/etc., etc. disabling gateway monitoring action doesn't mean that other processes/services and packages won't still 'react' to a link going down.

[stephenw10]

Mmm, can you try a switch between the WAN and the modem so it never actually loses link?

[stephenw10]

Ok try running this from the console when it stops responding:

dtrace -n 'fbt::_task_fn_rx:entry' -n 'fbt::_task_fn_tx:entry' -n 'fbt::_task_fn_iov:entry' -n 'fbt::_task_fn_admin:entry' -n 'fbt::_task_fn_rx_watchdog:entry'

One of those things is probably stuck and firing off numerous times.