How to prevent DHCPD log file spamming?

[sbellon]

Hi all,

I noticed on the dashboard that the used space on /var/log increased recently. So I did a "du --si -s *" in /var/log and found the subfolder dhcpd as the culprit:

Code: [Select]

root@opnsense:/var/log/dhcpd # ls -al
total 3573809
drwx------   2 root  wheel          34 Apr 12 11:01 .
drwxr-xr-x  20 root  wheel          44 Apr 12 09:21 ..
-rw-------   1 root  wheel      244116 Mar 13 23:57 dhcpd_20220313.log
-rw-------   1 root  wheel      219833 Mar 14 23:55 dhcpd_20220314.log
-rw-------   1 root  wheel      208801 Mar 15 23:59 dhcpd_20220315.log
-rw-------   1 root  wheel      207357 Mar 16 23:58 dhcpd_20220316.log
-rw-------   1 root  wheel      198017 Mar 17 23:55 dhcpd_20220317.log
-rw-------   1 root  wheel      211938 Mar 18 23:57 dhcpd_20220318.log
-rw-------   1 root  wheel      220304 Mar 19 23:55 dhcpd_20220319.log
-rw-------   1 root  wheel      207230 Mar 20 23:59 dhcpd_20220320.log
-rw-------   1 root  wheel      203665 Mar 21 23:59 dhcpd_20220321.log
-rw-------   1 root  wheel      224149 Mar 22 23:59 dhcpd_20220322.log
-rw-------   1 root  wheel      216169 Mar 23 23:59 dhcpd_20220323.log
-rw-------   1 root  wheel      223937 Mar 24 23:57 dhcpd_20220324.log
-rw-------   1 root  wheel      220520 Mar 25 23:59 dhcpd_20220325.log
-rw-------   1 root  wheel      229024 Mar 26 23:56 dhcpd_20220326.log
-rw-------   1 root  wheel      271634 Mar 27 23:55 dhcpd_20220327.log
-rw-------   1 root  wheel      251120 Mar 28 23:56 dhcpd_20220328.log
-rw-------   1 root  wheel      265486 Mar 29 23:55 dhcpd_20220329.log
-rw-------   1 root  wheel      272309 Mar 30 23:55 dhcpd_20220330.log
-rw-------   1 root  wheel      264335 Mar 31 23:56 dhcpd_20220331.log
-rw-------   1 root  wheel      304474 Apr  1 23:55 dhcpd_20220401.log
-rw-------   1 root  wheel      260829 Apr  2 23:55 dhcpd_20220402.log
-rw-------   1 root  wheel  1493859272 Apr  3 23:59 dhcpd_20220403.log
-rw-------   1 root  wheel  6547501137 Apr  4 23:59 dhcpd_20220404.log
-rw-------   1 root  wheel  6512845136 Apr  5 23:59 dhcpd_20220405.log
-rw-------   1 root  wheel  6516743124 Apr  6 23:59 dhcpd_20220406.log
-rw-------   1 root  wheel  6675526139 Apr  7 23:59 dhcpd_20220407.log
-rw-------   1 root  wheel  6508607429 Apr  8 23:59 dhcpd_20220408.log
-rw-------   1 root  wheel  6483174952 Apr  9 23:59 dhcpd_20220409.log
-rw-------   1 root  wheel  6720341313 Apr 10 23:59 dhcpd_20220410.log
-rw-------   1 root  wheel  6940561135 Apr 12 00:00 dhcpd_20220411.log
-rw-------   1 root  wheel  3513974130 Apr 12 11:40 dhcpd_20220412.log
lrwxr-x---   1 root  wheel          33 Apr 12 11:01 latest.log -> /var/log/dhcpd/dhcpd_20220412.log

First I assumed that the last 7 (or 10) days would be plaintext and older ones are compressed, but this is not the case.

It could be connected to an upgrade from 22.1.x to the latest 22.1.5, but I'm not sure how to verify that.

Any ideas?

[sbellon]

Further investigation (i.e. comparison of the log files before the increase vs. after the increase) has shown that I now get a MASSIVE amount of messages of the following form (in immediate succession), that were not present before:

Code: [Select]

Renew message from fe80::xxxx:xxxx:xxxx:xxxx port 546, transaction ID 0xXXXXXXXX
Reply NA: address 2003:xx:xxxx:xxxx::xxxx to client with duid xx:xx:xx:xx:xx:xx:xx:xx:xx:xx iaid = 3 valid for 7200 seconds
Reusing lease for: 2003:xx:xxxx:xxxx::xxxx, age 755 secs < 25%, sending shortened lifetimes - preferred: 2, valid 6445
Sending Reply to fe80::xxxx:xxxx:xxxx:xxxx port 546

Whereas before I *occasionally* had those:

Code: [Select]

Renew message from fe80::xxxx:xxxx:xxxx:xxxx port 546, transaction ID 0xXXXXXXXX
Reply NA: address 2003:xx:xxxx:xxxx::xxxx to client with duid xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx iaid = -339651575 valid for 7200 seconds
Sending Reply to fe80::xxxx:xxxx:xxxx:xxxx port 546

Does this ring any bell?

[sbellon]

On further debugging I found out that the duid is always for the same device (HP Color LaserJet Pro MFP M281fdw) which received a firmware update a few days ago (it could have been exactly 10 days ago, can't say for sure though).

Doing a "tail -f" on the dhcpd log emitted ~500 messages per second.

Then I decided to reboot the printer and since then, the message spamming has stopped. Fingers crossed that it stays that way, I'll keep monitoring.

Perhaps somebody who understands the dhcpd logs can give me a hint on what exactly went wrong and why the OPNsense kept moaning about it with such an insistence.

[sbellon]

Ok, soon after the reboot, the old "log spamming behaviour" occurred again.

So, even if this is not the fault of the OPNsense, this is filling up my log partition quite fast.

I'd like to find out what the reason is and how to fix it - or at least how to disable this kind of logging without disabling DHCPD logging completely.

Any ideas?

[crpb]

Yesterday i got the same behavior. I thought someone did a bad Job at the Cabling.

Prior to detecting this error i thought it was a Update-Error because the device was offline for a couple of months.
After reinstalling the opnSense via IPMI over WAN (which took forever) i gathered that the problems were due to the dhcpd.

A _short_ Log from yesterday where you see how many requests were made in alone one second
https://moep.com/dhcpd_20220412.log 44k lines
It looks like this when activating the DHCPd.
https://moep.com/DHCPD-HAT-ZU-TUN.mp4

As it seems other installations now also have some problems... Will forther investigate.