Memory getting saturated

[mmaridev]

Hi,

upgraded almost 2 weeks ago from 21 and now having a problem with the RAM. Its usage gets higher and higher up to when important processes like unbond get killed and the network stops working.
Had nothing like this before the upgrade. Any clue?

Thanks in advance,

[clvrmnky]

I've noticed a lot of memory being used and not being freed. So far it isn't climbing, but my uptime has only been a few days with 22.1.

What are the top size and res in System: Diagnostics: Activity for you? I see many unbound and netdata threads chewing up lots of memory. Top X threads:

20667   unbound   20   0   1066M   882M   kqread   2   0:00   0.03%   /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
   20667   unbound   20   0   1066M   882M   kqread   0   1:39   0.01%   /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
   20667   unbound   20   0   1066M   882M   kqread   3   0:00   0.00%   /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
   20667   unbound   20   0   1066M   882M   kqread   2   0:00   0.00%   /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
   3127   netdata   40   19   130M   57M   nanslp   2   0:07   0.23%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{PLUGIN[freebsd]}
   3127   netdata   40   19   130M   57M   piperd   3   0:01   0.03%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{PLUGINSD[apps]}
   3127   netdata   40   19   130M   57M   nanslp   2   0:01   0.03%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{PLUGIN[idlejitt}
   3127   netdata   40   19   130M   57M   piperd   1   0:01   0.02%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{PLUGINSD[python}
   3127   netdata   40   19   130M   57M   piperd   0   0:01   0.02%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{PLUGINSD[charts}
   3127   netdata   40   19   130M   57M   nanslp   1   0:00   0.01%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{GLOBAL_STATS}
   3127   netdata   40   19   130M   57M   nanslp   3   0:00   0.01%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{STATSD}
   3127   netdata   40   19   130M   57M   kqread   1   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{DBENGINE}
   3127   netdata   40   19   130M   57M   select   2   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{WEB_SERVER[stat}
   3127   netdata   40   19   130M   57M   select   1   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{WEB_SERVER[stat}
   3127   netdata   40   19   130M   57M   select   1   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{WEB_SERVER[stat}
   3127   netdata   40   19   130M   57M   select   2   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{STATSD_COLLECTO}
   3127   netdata   40   19   130M   57M   select   0   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{WEB_SERVER[stat}
   3127   netdata   52   19   130M   57M   pause   0   0:01   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{netdata}
   3127   netdata   40   19   130M   57M   nanslp   2   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{HEALTH}
   3127   netdata   40   19   130M   57M   nanslp   2   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{PLUGINSD}
   3127   netdata   40   19   130M   57M   nanslp   2   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{SERVICE}
   3127   netdata   40   19   130M   57M   uwait   3   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{netdata}
   3127   netdata   40   19   130M   57M   kqread   0   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{DAEMON_SPAWN}
   3127   netdata   40   19   130M   57M   uwait   0   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{netdata}
   3127   netdata   40   19   130M   57M   uwait   0   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{netdata}
   3127   netdata   40   19   130M   57M   uwait   2   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{netdata}
   3127   netdata   52   19   130M   57M   kqread   2   0:00   0.00%   /usr/local/sbin/netdata -u netdata -P /var/db/netdata/netdata.pid{DAEMON_COMMAND}
   19798   root   52   0   62M   42M   accept   1   0:02   0.00%   /usr/local/bin/php-cgi
   451   root   52   0   72M   39M   accept   0   0:01   0.00%   /usr/local/bin/python3 /usr/local/opnsense/service/configd.py console (python3.{python3.8}
   451   root   52   0   72M   39M   wait   3   0:00   0.00%   /usr/local/bin/python3 /usr/local/opnsense/service/configd.py console (python3.{python3.8}
   43400   netdata   40   19   63M   33M   select   0   0:06   0.19%   /usr/local/bin/python3.8 /usr/local/libexec/netdata/plugins.d/python.d.plugin 1{python3.8}
   43400   netdata   40   19   63M   33M   select   3   0:05   0.02%   /usr/local/bin/python3.8 /usr/local/libexec/netdata/plugins.d/python.d.plugin 1{python3.8}
   1941   root   20   0   48M   32M   select   1   0:52   0.01%   /usr/local/bin/python3 /usr/local/opnsense/scripts/netflow/flowd_aggregate.py (python3.
   77770   root   20   0   53M   31M   select   0   0:03   0.00%   /usr/local/bin/php-cgi
   43499   root   21   0   49M   29M   accept   1   0:02   0.00%   /usr/local/bin/php-cgi
   16758   root   52   0   47M   27M   accept   1   0:02   0.00%   /usr/local/bin/php-cgi
   44900   root   20   0   47M   26M   accept   1   0:02   0.00%   /usr/local/bin/php-cgi
   43818   root   52   0   47M   25M   accept   3   0:02   0.00%   /usr/local/bin/php-cgi

[j_s]

I'm having similar issues.

Let me start with this though... I don't typically recommend enabling netdata unless it is necessary.  At my prior employer we had so many problems with netdata memory leaks that we decided to disable it except when doing diagnostic testing.  I don't know if that will solve your problem, but it definitely won't solve mine.

For me, in top unbound wants to use 9GB of RAM.  This is a business with about 40 bitcoin miners on it.  They all point to the same place, and I have no explanation for how/why unbound would need that much RAM.  I haven't done anything crazy with unbound to explain this behavior.

I got an alert that my RAM is now 96% full (system has 8GB of RAM) and is up to date.

Anyone aware of any memory leak or other issue with Unbound?  I'm tempted to restart the service just to hopefully get unbound under control.  But ideally I like to troubleshoot the problem and fix it permanently rather than a temporary fix like restarting a service.  Notice in the screenshots that its even started using swapspace.  I've ordered more RAM for this box so it can be upped to 16GB, but I got this strong suspicion that unbound will eventually fill that up too.

[clvrmnky]

There isn't any real reason I enabled Netdata. It's not like I need that sort of visibility into things. I might have been using it to inspect IPv6 traffic a bit deeper.

I ended up disabling it right after posting my reply, and didn't see any change in memory use -- maybe a slight drop.

Hours later it's back up to 65-70%92% All unbound, python3, PHP and syslog-ng.

Something different is going on with 22.1.

[j_s]

So after I posted that, an update came out to 22.1.1_1, which I updated yesterday evening.  Naturally, the reboot reset the memory usage.  I'm at 2.2GB of RAM used now, and I'm going to continue to monitor it.  Right now unbound is at 1.3GB of RAM.  I'll provide more updates as time goes on.

[clvrmnky]

Are you using blocklists in unbound? It looks like some blocklists are blowing out memory on each unbound process/thread. Even starting/stopping unbound is painful and error-prone with some blocklists.

And NetFlow , if you have it enabled, also seems to be a memory hog now. Hard to disable it, though. I had to "Clear All" all the settings and reboot, which took a long time because between NetFlow, unbound, and the unbound control processes something was stuck.

I removed one of the blocklists and restarted unbound and I'm back to 40% in the dashboard. unbound processes are HUGE now, but they are smaller with smaller blocklists. And the processes that start/stop them don't spike the CPU.

There is another thread where unbound and blocklists is causing CPU spikes and +20C more heat in some smaller boxes.

[j_s]

I'm not using any blocklists.  The feature is disabled in my WebGUI.

However a quick update.  I've updated to 22.1.1_3 (no reboot required for that update, so none was performed) but in less than 12 hours, I'm now at 2.8GB of RAM used by the system, and 1.8GB for unbound.  So the system is using about 500MB of RAM more than it was less than 12 hours ago, and nearly 100% of that is for unbound exclusively.

Something seems very amiss with Unbound.  But I'm not an unbound expert, so I'm not even sure where to go to start troubleshooting this.  One thing I've changed relatively recently is that I added a domain override to another DNS server at our primary site.  Basically each site has it's own DNS, and each site is supposed to do DNS lookups to other site's DNS to resolve IPs within the company.  After removing the override and restarting unbound to apply the changes, unbound is now using 203MB of RAM.  So I'll monitor for the next 24-48 hours.

Another thing I find a bit odd is that when I try to look at the logging for Unbound DNS under Services -> Unbound DNS -> Log File nothing actually lists.  Basically I have two options... clear log and download log.  The place where the logging normally appears just sits there and shows "Loading..." and I see that each time I load the page another python 3.8 process loads and goes to 100%.  After I enabled the multiselect option and chose all of them, I had a number of processes at 100% on the router.  Each one spawned when I checked another one of the level of logging to display, and they all seemed to get stuck and run at 100%.

root    17645   0.0  0.3  32328 22024  -  Is   06:01       0:03.33 |-- /usr/local/bin/python3 /usr/local/opnsense/service/configd.py (python3.
root    26456   0.0  0.3  65236 27904  -  I    06:01       0:03.74 | `-- /usr/local/bin/python3 /usr/local/opnsense/service/configd.py console (python3.
root    59161 100.0  0.2  25036 13692  -  R    08:06       1:56.32 |   |-- /usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 0 --offset 0 --f                                                            ilter --module core --filename resolver --severity Emergency,Alert,Critical,Error,Warning (python3.
root    74015 100.0  0.2  25292 14020  -  R    08:04       3:56.40 |   |-- /usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 20 --offset 0 --                                                            filter --module core --filename resolver --severity Emergency,Alert,Critical,Error,Warning (python3.
root    98532 100.0  0.2  25036 13692  -  R    08:07       0:59.04 |   |-- /usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 20 --offset 0 --                                                            filter --module core --filename resolver --severity Warning (python3.
root    98575 100.0  0.2  25036 13692  -  R    08:07       0:58.54 |   |-- /usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 20 --offset 0 --                                                            filter --module core --filename resolver --severity Emergency,Warning (python3.
root    98721 100.0  0.2  25036 13692  -  R    08:07       0:58.18 |   |-- /usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 20 --offset 0 --                                                            filter --module core --filename resolver --severity Emergency,Alert,Warning (python3.
root    98773 100.0  0.2  25036 13692  -  R    08:07       0:57.84 |   |-- /usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 20 --offset 0 --                                                            filter --module core --filename resolver --severity Emergency,Alert,Critical,Warning (python3.
root    99094 100.0  0.2  25036 13692  -  R    08:07       0:57.44 |   `-- /usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 20 --offset 0 --                                                            filter --module core --filename resolver --severity Emergency,Alert,Critical,Error,Warning (python3.


I started writing this post, and then the WebGUI returned this:

{"errorMessage":"/usr/local/opnsense/mvc/app/controllers/OPNsense/Base/ApiControllerBase.php:96: Error at /usr/local/opnsense/mvc/app/controllers/OPNsense/Diagnostics/Api/LogController.php:105 - Trying to access array offset on value of type null (errno=8)","errorTrace":"#0 /usr/local/opnsense/mvc/app/controllers/OPNsense/Diagnostics/Api/LogController.php(105): OPNsense\\Base\\ApiControllerBase->APIErrorHandler(8, 'Trying to acces...', '/usr/local/opns...', 105, Array)\n#1 [internal function]: OPNsense\\Diagnostics\\Api\\LogController->__call('coreAction', Array)\n#2 [internal function]: Phalcon\\Dispatcher\\AbstractDispatcher->callActionMethod(Object(OPNsense\\Diagnostics\\Api\\LogController), 'coreAction', Array)\n#3 [internal function]: Phalcon\\Dispatcher\\AbstractDispatcher->dispatch()\n#4 /usr/local/opnsense/www/api.php(26): Phalcon\\Mvc\\Application->handle('/api/diagnostic...')\n#5 {main}","errorTitle":"An API exception occured"}

The opnsense box became very sluggish as I maxed out all 8 CPUs on the system, and load averages went over 10.  As its 6AM here, I do not have the option of rebooting the opnsense box.  This box was intended as a stop-gap while we got our HA system up and running, so a reboot takes that site down.  As nobody is onsite, and a few workloads will go haywire if the internet goes down, I'm stuck waiting for either someone to arrive at the office to assist me during the opnsense reboot or the python processes eventually timeout or otherwise terminate.  Right now they've been running for almost 15 minutes, so I'm getting a little concerned that they aren't going to do either and keep running at 100%.

[Fright]

@j_s
have you tried to reset logs?
System: Settings: Logging

[cookiemonster]

I am not certain is the place to look but I see /var/log/resolver/resolver_{date}.log that seems to be unbound logs.

[j_s]

@j_s
have you tried to reset logs?
System: Settings: Logging

I couldn't find it earlier.  I was up at 3AM because I couldn't sleep.  However, I just reset the logging, and now the logging works in Unbound properly.  Thanks for that!

I am not certain is the place to look but I see /var/log/resolver/resolver_{date}.log that seems to be unbound logs.

Yeah, I am gonna let this run for 24 hours or so with the settings changes.  Once that is determined to be fine, I'll try re-enabling the stuff I disabled (we really do need working DNS cross-site, but not in the short term) and then I'll monitor the logging.  I tried looking for unbound.log and others, but not that particular file.  As the logs are reset, I don't have them to look at right now.  But if my next post involved "the problem is back" you can bet I'll be looking at that log file.

Thanks everyone.  Currently going to monitor over the weekend and wait.

[j_s]

Okay, so it's been less than 12 hours and unbound is already over 1GB of RAM used.

The resolver logs are clearly identifying the issue:

Code: [Select]

<165>1 2022-02-18T21:04:51-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9890"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.94.
<165>1 2022-02-18T21:04:51-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9891"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.96.
<165>1 2022-02-18T21:04:51-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9892"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.98.
<165>1 2022-02-18T21:04:51-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9893"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.97.
<165>1 2022-02-18T21:04:51-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9894"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.99.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9895"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.137.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9896"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.141.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9897"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.131.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9898"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.122.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9899"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.129.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9900"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.138.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9901"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.128.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9902"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.124.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9903"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.109.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9904"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.125.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9905"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.121.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9906"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.110.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9907"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.127.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9908"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.133.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9909"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.101.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9910"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.108.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9911"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.107.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9912"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.134.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9913"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.102.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9914"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.35.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9915"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.89.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9916"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.95.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9917"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.93.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9918"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.90.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9919"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.91.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9920"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.117.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9921"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.116.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9922"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.115.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9923"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.140.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9924"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.139.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9925"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.142.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9926"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.132.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9927"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.135.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9928"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.113.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9929"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.126.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9930"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.112.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9931"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.118.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9932"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.111.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9933"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.119.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9934"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.120.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9935"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.123.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9936"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.136.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9937"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.130.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9938"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.104.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9939"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.105.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9940"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.100.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9941"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.114.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9942"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.47.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9943"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.103.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9944"] dhcpd entry changed WhatsMiner.site.business @ 172.18.10.6.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9945"] dhcpd entry changed WhatsMiner.site.business @ 172.18.10.17.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9946"] dhcpd entry changed WhatsMiner.site.business @ 172.18.10.4.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9947"] dhcpd entry changed WhatsMiner.site.business @ 172.18.10.7.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9948"] dhcpd entry changed WhatsMiner.site.business @ 172.18.10.34.
<165>1 2022-02-18T21:04:54-05:00 tempfirewall.site.business unbound 44293 - [meta sequenceId="9949"] dhcpd entry changed WhatsMiner.site.business @ 172.18.12.94.

The log from the last 12ish hours is already 75MB, and it's just chocked full of 450,000 ines of this stuff.  If I grep out everything with "Whatsminer" I get about 100 lines of logging from that 75MB file.  So the redundant name (or those devices themselves) seem to be a problem somehow.  I think I might rename one of them and see if it disappears from the logs.


We have two /24 subnets (172.18.12.x and 172.17.10.x) and a bunch of whatsminers being tested.

For our testing, I had dhcp leases default to 1200 seconds and maximum of 1800 seconds.  We went short because we were testing things with DHCP and DNS, and having a shorter renewal time allowed us to test stuff faster.  However, if you look at the above snippet, the same IP is at the top and bottom... just 3 seconds apart.  The logs are nothing but these entries, with never more than 3-4 seconds between them.

We also kept the default name because they're simply for testing, and will get a final name when they go to their final location.

In a future production environment we really want to have the leases with a relatively short time.  I was thinking an hour or two to coincide with the old RFC1541 spec although there is no minimum anymore from what I remember.

So is the problem that all these devices have the same hostname and unbound isn't enjoying that at all?  Naturally, if I do a DNS lookup for that device name, I get all of the devices.  Useless, for actual DNS resolution, but not something I'm upset about as we're just testing and they will eventually be renamed to their final names.

I did grab one device that was showing up nonstop in the list, and I changed its name to something unique, and the log entries for that specific IP stopped immediately.  So i'm inclined to think having 80+ devices with the same name is "not good to do", even if we're just lazy and trying to do testing.

Anyone agree or disagree with this, or offer any insight into this?  I'd love to understand this behavior better.
 

[Fright]

having 80+ devices with the same name is "not good to do", even if we're just lazy and trying to do testing

for this particular case (test environment, short lease time, same hosts names etc), does it even make sense to register leases on unbound?
imho this only gives an excessive load on the server and the log.

[j_s]

having 80+ devices with the same name is "not good to do", even if we're just lazy and trying to do testing

for this particular case (test environment, short lease time, same hosts names etc), does it even make sense to register leases on unbound?
imho this only gives an excessive load on the server and the log.

So I would say both yes and no.

Yes, because in our production environment, we now know we need to add a singular device and change the name, then go to the next device instead of powering on a ton of devices with identical names thinking that at some point "in the future" we'll rename them and then walking away for long periods of time.  Quite literally, we simply didn't rename them because we were lazy and figured this would give us pre-production time to iron out any bugs we might have with the systems and network infrastructure along with building construction that is ongoing.  We also may or may not have control of the hostnames in some cases, so this would clearly be a serious problem if we didn't have access to change the hostnames.  For me, internally, I now know about this issue and I need to be able to raise a red flag if this does happen.

At the same time, "no", because this really shouldn't have happened.  Generally, it's an obvious bad idea to even have 2 devices with the same hostname. 

I'm generally a fan of "do it once and do it right" rather than doing it twice (or more than twice).

I do really wish that you could tell dhcpd not to give out dhcp leases to two devices with the same name, but I asked that https://forum.opnsense.org/index.php?topic=25612 and nobody responded, so either my question is "you idiot, why are you wanting this" (entirely possible, I do stupid things sometimes) or there really isn't a way.  I did try to read up the docs on dhcpd, and I didn't see any obvious way to simply deny duplicate hostnames.  But back to the issue with this thread.

This also breaks viewing of the logs and could cause production down situations.  Unbound (and the WebGUI) doesn't expect to parse files sized in 10s of MB or more.  Like I mentioned above, trying to view the logs in the WebGUI ultimately took the router's CPU to 100%.  While that didn't seem to have any consequences "this time" I may not be so lucky the next time.

So at this stage, it is important for me to consider that duplicate hostnames are bad and need to be weeded out as a high priority in a production environment.  Additionally, having a VLAN that is a "test environment" will also not avoid potential catastrophe for the production environment unless I'm going to have independent dhcp and/or dns that is somehow isolated from the production systems so as to avoid problems.

Quick data point as well:  I did a "drill whatsminer.site.business" and I got these fun 2 lines at the end of the query...

;; WARNING: The answer packet was truncated; you might want to
;; query again with TCP (-t argument), or EDNS0 (-b for buffer size)

That to me is Unbound laughing at me for being dumb.

[Fright]

i have noticed one call on your logs:

/usr/local/bin/python3 /usr/local/opnsense/scripts/systemhealth/queryLog.py --limit 0 --offset 0

did you really request an unbond logs without limiting the number of rows returned? then I think this can also be a problem (and maybe its better to either remove this option or limit resources for queryLog.py script)

[exuvo]

I have had the same problem after the new release and in my case the culprit was firewall logs were growing to 700MB per day (in /var/log/filter which is tmpfs).

Not sure if log settings got reset or something but i unchecked "Log packets matched from the default pass rules put in the ruleset" which was responsible for the majority of log messages and also lowered "Preserve logs (Days)" to 3 days (from default 31 days).

Attached the last 60 hour memory graph, empty space is from lost data as my router ran out of memory and started killing all processes. Could not even ssh in but saw the OOM messages on the connected monitor.