dhcpd Logfiles are getting huge (7GB/Day!)

[dati]

Hello,

i've noticed that my system drive was filled very quickly.
It turned out that the logs in /var/log/dhcpd are getting very large (about 7GB/day).
Every Day a new log file gets created with the name /var/log/dhcpd/dhcpd_yyyymmdd.log.
The first day with such a log file was the 28th january - the day I've installed 22.1.

The log file looks like this:

Code: [Select]

<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488576"] Renew message from fe80::de4a:3eff:feb4:844f port 546, transaction ID 0xDC7BD600
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488577"] Reply NA: address 2a00:xxxx:xxxx:xxxx::988 to client with duid de:ad:be:ef:de:ad:be:ef:de:ad iaid = 2 valid for 600 seconds
<191>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488578"] Reusing lease for: 2a00:xxxx:xxxx:xxxx::988, age 147 secs < 25%, sending shortened lifetimes - preferred: 1, valid 453
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488579"] Sending Reply to fe80::de4a:3eff:feb4:844f port 546
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488580"] Renew message from fe80::de4a:3eff:feb4:844f port 546, transaction ID 0xE3DFB300
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488581"] Reply NA: address 2a00:xxxx:xxxx:xxxx::988 to client with duid de:ad:be:ef:de:ad:be:ef:de:ad iaid = 2 valid for 600 seconds
<191>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488582"] Reusing lease for: 2a00:xxxx:xxxx:xxxx::988, age 147 secs < 25%, sending shortened lifetimes - preferred: 1, valid 453
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488583"] Sending Reply to fe80::de4a:3eff:feb4:844f port 546
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488584"] Renew message from fe80::de4a:3eff:feb4:844f port 546, transaction ID 0x19FF9E00
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488585"] Reply NA: address 2a00:xxxx:xxxx:xxxx::988 to client with duid de:ad:be:ef:de:ad:be:ef:de:ad iaid = 2 valid for 600 seconds
<191>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488586"] Reusing lease for: 2a00:xxxx:xxxx:xxxx::988, age 147 secs < 25%, sending shortened lifetimes - preferred: 1, valid 453
<190>1 2022-02-07T17:33:24+01:00 DG-OPNsense.localdomain dhcpd 74312 - [meta sequenceId="488587"] Sending Reply to fe80::de4a:3eff:feb4:844f port 546

I can't really find out what is happening there.
But it seems that OPNsense talks to a device with the duid de:ad:be:ef:de:ad:be:ef:de:ad (i did not change this!) that is spaming the logs.

Because the first large log file was dhcpd_20220128.log, my problem might have something to do with the 22.1 upgrade.

I am running a DHCPv6 Service on the OPNsense.
Can someone explain to me what is happening there?

[Vesalius]

Likely reason given here.

https://forum.opnsense.org/index.php?topic=26778.msg129719#msg129719

[kiwibob]

I have the same problem as OP with 12GB of file since last night. The system has crashed twice since the upgrade with no disk space left

While limiting the days to keep the log file as suggested is certainly helpful in keeping the system up I wonder what has changed as this seems a new problem since 22.1 and this amount of logging would appear to indicate an issue?

[franco]

Circular logging is no longer supported in 22.1. Depending on the work that DHCP server has to do (number of clients using it for whatever reason) logging can be larger or smaller.


Cheers,
Franco

[kiwibob]

I don't think that the problem is the removal of circular logging.

In the first second of the new log today there were just under 2000 new entries. It's hard to see why dhcp would need to generate this level of logging on a domestic network with less than 40 active clients?

The message suggests that a lease has a very short life generating excess work for dhcpd?

Code: [Select]

<190>1 2022-03-03T00:00:00+13:00 OPNsense.xxxx.co.nz dhcpd 76891 - [meta sequenceId="1980"] Sending Reply to fe80::240:8cff:fe93:f120 port 546
<190>1 2022-03-03T00:00:01+13:00 OPNsense.xxxx.co.nz dhcpd 76891 - [meta sequenceId="1981"] Renew message from fe80::240:8cff:fe93:f120 port 546, transaction ID 0x7CE8EB00
<190>1 2022-03-03T00:00:01+13:00 OPNsense.xxxx.co.nz dhcpd 76891 - [meta sequenceId="1982"] Reply NA: address 2406:xxxx:x:xxxx::1234 to client with duid 00:03:00:01:00:40:8c:93:f1:20 iaid = 2 valid for 7200
 seconds
<191>1 2022-03-03T00:00:01+13:00 OPNsense.xxxx.co.nz dhcpd 76891 - [meta sequenceId="1983"] Reusing lease for: 2406:xxxx:x:xxxx::1234, age 1404 secs < 25%, sending shortened lifetimes - preferred: 1, valid
5796

[franco]

You don't think so and I simply don't know.


Cheers,
Franco

[cookiemonster]

Does the level of log verbosity in "Services > DHCPv4 > Log File" change it only for the view on the UI at the time, or does it also change it in a configuration setting? For anyone who knows.
I ask in case there's a way to limit the level that goes to the file.

kiwibob, my network is similar in size and the files are not huge. About 7.5 K lines per day.

line count :

Code: [Select]

% sudo cat /var/log/dhcpd/dhcpd_20220301.log | wc -l
    7631
 % sudo cat /var/log/dhcpd/dhcpd_20220302.log | wc -l
    7144
file size:

Code: [Select]

% sudo ls -alh /var/log/dhcpd/dhcpd_20220301.log
-rw-------  1 root  wheel   1.1M Mar  1 23:59 /var/log/dhcpd/dhcpd_20220301.log

% sudo ls -alh /var/log/dhcpd/dhcpd_20220302.log
-rw-------  1 root  wheel   1.0M Mar  2 22:22 /var/log/dhcpd/dhcpd_20220302.log
Point being, maybe something needs tweaking. Have you tried restarting the DHCPd daemon?

[kiwibob]

Turns out it may have been a dodgy IPv6 device (an antique cctv camera). 

I restarted DHCPD6 and the problem stopped.  I suspect it would have restarted later anyway I identified the device  using the DUID in the log and searched the IPv6 leases. The device is now IPv4 only and scheduled for replacement.

So far the log file is behaving normally.