rsyslog not keeping up with dhcpd SOLVED

Tue Apr 12 16:00:45 UTC 2016

Thanks everyone for all of the advice!!!  It did help, and here's what I 
had to do:

/etc/rsyslog.conf:
	$SystemLogRateLimitInterval     0
	$IMUXSockRateLimitInterval      0
	$IMJournalRatelimitInterval	0

/etc/systemd/journald.conf:
	[Journal]
	RateLimitInterval=0
	RateLimitBurst=0

Followed by, of course:

systemctl restart systemd-journald.service
systemctl restart rsyslog.service

I found an entry at stackoverflow that helped immensely, and here's the 
citation:

http://stackoverflow.com/questions/33041593/centos-7-rsyslog-debug-logs-dropped-for-c-c-modules

I did not set (as per that site entry) the following in 
/etc/systemd/journald.conf:

Storage=volatile
Compress=no
MaxRetentionSec=5s

Thanks all!

Alex

On 04/08/2016 03:33 PM, dave c wrote:
> 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
>>
>

-- 
Alex Moen
NSTII
North Dakota Telephone Company
701-662-6481