rsyslog not keeping up with dhcpd

[dave c]

In addition to the likely rate limiting, I've seen where disk write contention between the 
leases file and the local syslog can cause issues. Which is why I only send my DHCP logs to an 
external pair of log servers. This allows me to optimize my log servers for nothing but log 
appending and have enough storage to keep my logs for 13+ months. Meanwhile, the DHCP servers 
are purring along and only worrying about minor incidental local logging and the leases file.

Dave

On 4/8/16 14:18, John Miller wrote:
> Hi Alex,
>
> rsyslog does rate-limiting by default in RHEL 6.  Not sure if it's on
> by default in RHEL 7; if it is, you'll see messages like:
>
> Jul  3 08:50:17 localhost rsyslogd-2177: imuxsock begins to drop
> messages from pid 4713 due to rate-limiting
>
> in /var/log/messages.  Worth a double-check.
>
> John
>
>
> On Fri, Apr 8, 2016 at 2:43 PM, Alex Moen <alexm at ndtel.com> wrote:
>> I have a virtual Centos7 machine on IBM ESX hardware. It is being utilized
>> as a DHCP server for the ISP that I work for. It seems that rsyslog is not
>> keeping up with the logging that dhcpd is generating, or dhcpd is not
>> sending the logs to rsyslog.
>>
>> First of all, dhcpd is issuing between 20 and 40 leases per second,
>> according to /var/state/dhcpd/dhcpd.leases. If I tail -f /var/log/dhcpd, I
>> will see log entries flow for about 5 seconds, then 25 seconds of nothing,
>> then another 5 seconds of logs, then 25 seconds of nothing... and so on.
>> This is very predictable, and changes very little, offsetting a few log
>> entries at a time so the logging times creeps forward slowly. If I tail -f
>> /var/state/dhcpd/dhcpd.leases, the lease file is constantly being updated,
>> no 25 second pause at any time. So, for the time being, I am blaming rsyslog
>> for not keeping up with dhcpd and giving the benefit of the doubt to dhcpd.
>>
>> I have looked at the performance graph for the virtual machine, and have not
>> seen any issues with hardware latency. There is plenty of CPU overhead, lots
>> of extra memory, and very low disk latency (<= 1 ms). Also, if there was an
>> issue with hardware, I would believe that I would see the same kind of
>> behavior in the lease file as I do in the log file.
>>
>> Top shows:
>>
>> top - 15:36:38 up 21 days, 6:22, 2 users, load average: 0.12, 0.11, 0.13
>> Tasks: 89 total, 4 running, 85 sleeping, 0 stopped, 0 zombie
>> %Cpu(s): 1.6 us, 1.6 sy, 0.0 ni, 96.8 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
>> KiB Mem : 3882828 total, 825304 free, 178580 used, 2878944 buff/cache
>> KiB Swap: 4095996 total, 4094748 free, 1248 used. 3193348 avail Mem
>>
>>
>> rsyslog.conf file contents:
>> cat /etc/rsyslog.conf
>>
>> $ModLoad imuxsock
>> $ModLoad imjournal
>> $WorkDirectory /var/lib/rsyslog
>> $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
>> $IncludeConfig /etc/rsyslog.d/*.conf
>> $OmitLocalLogging on
>> $IMJournalStateFile imjournal.state
>>
>> local4.* /var/log/dhcpd
>> local7.* /var/log/boot.log
>> *.info;mail.none;authpriv.none;cron.none;local4.none /var/log/messages
>> authpriv.* /var/log/secure
>> mail.* -/var/log/maillog
>> cron.* /var/log/cron
>> *.emerg :omusrmsg:*
>> uucp,news.crit /var/log/spooler
>>
>> The only file in /etc/rsyslog.d is listen.conf:
>> cat /etc/rsyslog.d/listen.conf
>>
>> $SystemLogSocketName /run/systemd/journal/syslog
>>
>>
>> Config pertaining to logging for dhcpd is:
>>
>> log-facility local4;
>> if exists agent.circuit-id
>> {
>> log ( info, concat(
>> "ALLIED TELESYN: OPTION82-INFO: Lease for ", binary-to-ascii (10, 8, ".",
>> leased-address),
>> " is connected on DSLAM ", ( option agent.remote-id),
>> " interface ", binary-to-ascii (10, 8, ".", substring( option
>> agent.circuit-id, 0, 2)),
>> ", using VLAN ", binary-to-ascii (10, 16, "", substring( option
>> agent.circuit-id, 2, 2))
>> ));
>>
>> log ( info, concat(
>> "PARADYNE: OPTION82-INFO: Lease for ", binary-to-ascii (10, 8, ".",
>> leased-address),
>> " agent-circuit-id info is: ", (option agent.circuit-id)
>> ));
>>
>> log ( info, concat(
>> "CALIX: OPTION82-INFO: Lease for ", binary-to-ascii (10, 8, ".",
>> leased-address),
>> " is connected on DSLAM ", ( option agent.remote-id ),
>> " VLAN and Port: ", ( option agent.circuit-id )
>> ));
>>
>> log ( info, concat(
>> "RAW DATA: Lease for ", binary-to-ascii (10, 8, ".", leased-address),
>> " raw option-82 info is CID: ", binary-to-ascii (10, 8, ".", option
>> agent.circuit-id),
>> " AID: ", binary-to-ascii (16, 8, ".", option agent.remote-id)
>> ));
>> }
>>
> _______________________________________________
> dhcp-users mailing list
> dhcp-users at lists.isc.org
> https://lists.isc.org/mailman/listinfo/dhcp-users
>

-- 
Dave Calafrancesco