rsyslog not keeping up with dhcpd

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

rsyslog not keeping up with dhcpd

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



I'm open to any suggestions or comments... I have rtfm'd, but I can't
find anything that pertains. I have also googled, but with no success.

Thanks for any help!

Alex
--
Alex Moen
NSTII
North Dakota Telephone Company
701-662-6481
_______________________________________________
dhcp-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/dhcp-users
Reply | Threaded
Open this post in threaded view
|

Re: 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 <[hidden email]> 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
[hidden email]
https://lists.isc.org/mailman/listinfo/dhcp-users
Reply | Threaded
Open this post in threaded view
|

Re: 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 <[hidden email]> 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
> [hidden email]
> https://lists.isc.org/mailman/listinfo/dhcp-users
>

--
Dave Calafrancesco
_______________________________________________
dhcp-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/dhcp-users
Reply | Threaded
Open this post in threaded view
|

Re: rsyslog not keeping up with dhcpd

Steve van der Burg
In reply to this post by John Miller
You can always remove rsyslog's rate limits like this:

  $SystemLogRateLimitInterval     0
  $IMUXSockRateLimitInterval      0

...Steve

John Miller <[hidden email]> 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 <[hidden email]> 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
> [hidden email]
> https://lists.isc.org/mailman/listinfo/dhcp-users

 --------------------------------------------------------------------------------
This information is directed in confidence solely to the person named above and may contain confidential and/or privileged material. This information may not otherwise be distributed, copied or disclosed. If you have received this e-mail in error, please notify the sender immediately via a return e-mail and destroy original message. Thank you for your cooperation.
_______________________________________________
dhcp-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/dhcp-users
Reply | Threaded
Open this post in threaded view
|

Re: rsyslog not keeping up with dhcpd SOLVED

Alex Moen
In reply to this post by dave c
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 <[hidden email]> 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
>> [hidden email]
>> https://lists.isc.org/mailman/listinfo/dhcp-users
>>
>

--
Alex Moen
NSTII
North Dakota Telephone Company
701-662-6481
_______________________________________________
dhcp-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/dhcp-users
Reply | Threaded
Open this post in threaded view
|

Re: rsyslog not keeping up with dhcpd

John Wobus
In reply to this post by dave c
On Apr 8, 2016, at 4:33 PM, dave c <[hidden email]> 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

+1

If syslog is having problems, your dhcp activity may be reaching the point where disk synchs
affect dhcpd performance.  Linux commands that show disk activity can show the issue
("why is the system with very light cpu activity doing huge numbers of disk synchs?”).
DHCP’s retries can hide a growing problem, which might cause a trouble that is non-linearly
related to load: no complaints, then suddenly many.

Logging via udp, or logging without synching eliminates some disk load.  For the lease file
writes, there are smart controllers with NV caching, there are solid state disks, there is a
dhcpd feature to batch disk writes (which may be ready for prime-time), or there is
ramdisk, which unfortunately seriously affects the resiliency of the dhcp service if the OS dies.
The dhcp load tester, dhcperf reveals a lot.

John Wobus
Cornell University IT

_______________________________________________
dhcp-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/dhcp-users
Reply | Threaded
Open this post in threaded view
|

Re: rsyslog not keeping up with dhcpd

Alex Moen
As stated in the original post, I have checked the disk I/O and there is
no issue there, nor with any other hardware.  I have already posted the
fix, and it is based on default settings in rsyslog to limit logging.
IMHO, that is a very poor decision, as any kind of rate limiting
decisions should be made by the system administrator and not the
software developer.  I have applied the configuration changes and all
the DHCPd logs are being written to disk now.

Thanks,

Alex


On 04/15/2016 12:14 PM, John Wobus wrote:

> On Apr 8, 2016, at 4:33 PM, dave c <[hidden email]> 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
>
> +1
>
> If syslog is having problems, your dhcp activity may be reaching the point where disk synchs
> affect dhcpd performance.  Linux commands that show disk activity can show the issue
> ("why is the system with very light cpu activity doing huge numbers of disk synchs?”).
> DHCP’s retries can hide a growing problem, which might cause a trouble that is non-linearly
> related to load: no complaints, then suddenly many.
>
> Logging via udp, or logging without synching eliminates some disk load.  For the lease file
> writes, there are smart controllers with NV caching, there are solid state disks, there is a
> dhcpd feature to batch disk writes (which may be ready for prime-time), or there is
> ramdisk, which unfortunately seriously affects the resiliency of the dhcp service if the OS dies.
> The dhcp load tester, dhcperf reveals a lot.
>
> John Wobus
> Cornell University IT
>
> _______________________________________________
> dhcp-users mailing list
> [hidden email]
> https://lists.isc.org/mailman/listinfo/dhcp-users
>

--
Alex Moen
NSTII
North Dakota Telephone Company
701-662-6481
_______________________________________________
dhcp-users mailing list
[hidden email]
https://lists.isc.org/mailman/listinfo/dhcp-users