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:
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?
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:
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:
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?
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.
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?
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.