rsyslog not keeping up with dhcpd

[John Miller]

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)
> ));
> }
>