[gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Steve]

Has anyone any ideas?  The syslog-ng is the usually the first line 
reported by top:

 4097 root      20   0  3120 1060  708 R 48.3  0.1 677:46.38 syslog-ng

The files in /var/log seem to be growing at an expected slow pace and 
aren't reporting anything unexpected.  I followed a 'howto' and have 
sshguard running.  This (comments stripped) is what I have in 
/etc/syslog-ng/syslog-ng.conf
> options {
>         chain_hostnames(off);
>         sync(0);
>         stats(43200);
> };
>
> source src {
>     unix-stream("/dev/log" max-connections(256));
>     internal();
>     file("/proc/kmsg");
> };
>
> destination messages { file("/var/log/messages"); };
> destination console_all { file("/dev/tty12"); };
> log { source(src); destination(messages); };
> log { source(src); destination(console_all); };
> destination authlog { file("/var/log/auth.log"); };
> destination authlog { file("/var/log/auth.log"); };
> filter f_authpriv { facility(auth, authpriv); };
> log { source(src); filter(f_authpriv); destination(authlog); };
> filter sshlogs { facility(auth, authpriv) and match("sshd"); };
> destination sshguardproc {
>     program("/usr/local/sbin/sshguard"
>         template("$DATE $FULLHOST $MESSAGE\n"));
>     };
>     log { source(src); filter(sshlogs); destination(sshguardproc); };

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Steve]

Steve wrote:
>> destination sshguardproc {
>>     program("/usr/local/sbin/sshguard"
>>         template("$DATE $FULLHOST $MESSAGE\n"));
>>     };
>>
The presence of the above line is definitely what triggers the excessive 
CPU usage - it is almost as-if syslog-ng is 'busy-waiting' for the 
sshguard process.  The sshguard process is running - but using zero CPU.

I have this problem with syslog-ng versions 2.1.3 and 2.1.4 (the one 
with ~x86)...

This is very frustrating... having played around, the syslog-ng tends 
towards using 100% CPU when my server is otherwise quiet - if, and only 
if, I have the program destination... even if the destination is not used.

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Steve]

Steve wrote:
> This is very frustrating... having played around, the syslog-ng tends 
> towards using 100% CPU when my server is otherwise quiet - if, and 
> only if, I have the program destination... even if the destination is 
> not used.

Oh, and strace shows syslog-ng frantically polling file-descriptor 3... 
which, I presume, is the pipe to the sshguard process.

> poll([{fd=6, events=0}, {fd=4, events=POLLIN}, {fd=10, events=POLLIN}, 
> {fd=3, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLIN}, 
> {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 8, 1178000) = 1 
> ([{fd=6, revents=POLLERR}])
> gettimeofday({1237836567, 385148}, NULL) = 0
> gettimeofday({1237836567, 385178}, NULL) = 0
> poll([{fd=6, events=0}, {fd=4, events=POLLIN}, {fd=10, events=POLLIN}, 
> {fd=3, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLIN}, 
> {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 8, 1178000) = 1 
> ([{fd=6, revents=POLLERR}])
> gettimeofday({1237836567, 385506}, NULL) = 0
> gettimeofday({1237836567, 385712}, NULL) = 0
> poll([{fd=6, events=0}, {fd=4, events=POLLIN}, {fd=10, events=POLLIN}, 
> {fd=3, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLIN}, 
> {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 8, 1178000) = 1 
> ([{fd=6, revents=POLLERR}])
> gettimeofday({1237836567, 386027}, NULL) = 0
> gettimeofday({1237836567, 386241}, NULL) = 0
Do others get this behaviour - is this a bug in syslog-ng?

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Alan McKinnon]

On Monday 23 March 2009 21:27:15 Steve wrote:
> Steve wrote:
> >> destination sshguardproc {
> >>     program("/usr/local/sbin/sshguard"
> >>         template("$DATE $FULLHOST $MESSAGE\n"));
> >>     };
>
> The presence of the above line is definitely what triggers the excessive
> CPU usage - it is almost as-if syslog-ng is 'busy-waiting' for the
> sshguard process.  The sshguard process is running - but using zero CPU.
>
> I have this problem with syslog-ng versions 2.1.3 and 2.1.4 (the one
> with ~x86)...
>
> This is very frustrating... having played around, the syslog-ng tends
> towards using 100% CPU when my server is otherwise quiet - if, and only
> if, I have the program destination... even if the destination is not used.

One word:

blocking

I find this is usually the cause for higher than normal CPU load as reported 
by top and other tools. If the load is pegged at exactly 100%, it's almost a 
sure sign that some process is IO blocking on an idle system, and all the 
process is doing is checking if IO is available, see it isn't, goes to sleep, 
wakes up, rinse and repeat.

In short: top lies, and load does not mean what most people think it means. 
The correct definition is "average number of processes that are waiting for 
cpu time within the measurement period." 

-- 
alan dot mckinnon at gmail dot com

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Sebastian Günther]

[-- Attachment #1: Type: text/plain, Size: 586 bytes --]

* Steve (gentoo_sjh@shic.co.uk) [23.03.09 20:27]:
> Steve wrote:
> >> destination sshguardproc {
> >>     program("/usr/local/sbin/sshguard"
> >>         template("$DATE $FULLHOST $MESSAGE\n"));
> >>     };
> >>

program() only takes 1 argument: the programname.

Any thing you want to pass, you have to define via a log statement.

BTW: Just curious: you do not use the sshguard from portage, or why is 
it a /usr/local/sbin?

HTH
Sebastian

-- 
 " Religion ist das Opium des Volkes. "      Karl Marx

 SEB@STI@N GÜNTHER         mailto:samson@guenther-roetgen.de

[-- Attachment #2: Type: application/pgp-signature, Size: 198 bytes --]

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Steve]

Steve wrote:
> Do others get this behaviour - is this a bug in syslog-ng?

Sorry for the multiple posts... a slight error on my part.  The sshguard 
process wasn't running - a /bin/sh process trying to spawn it was 
running (there was no link from /usr/local... to the binary) and when 
the binary failed to execute - syslog-ng got itself into a tiz.  
Everything seems to work fine when I correct the path to the program.

Problem solved - but, I guess, this is a flaw in syslog-ng... I'd have 
hoped it would generate an error message rather than behave as it did.

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Steve]

Sebastian Günther wrote:
> program() only takes 1 argument: the programname.
>   
There aren't two arguments (no comma) - and, yes, the syntax is odd - 
but it is exactly what is given by the sshguard man page - and seems to 
be confirmed by the syslog-ng manual, too.
> BTW: Just curious: you do not use the sshguard from portage, or why is 
> it a /usr/local/sbin?
>   
That was my error (a really dumb one!) I'd assumed that the binary from 
portage was running - whereas my process list showed /bin/sh failing to 
run a non-existent program.

I guess the man page could be improved for gentoo by giving an example 
using the default install location for sshguard - but that's a very 
minor issue.

I'd expected better error reporting by syslog-ng for a faulty 
configuration - ho-hum.

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Steve]

Alan McKinnon wrote:
> In short: top lies, 
>   
On this occasion, top was telling the truth. ;)

Re: [gentoo-user] Syslog-ng using a spectacular amount of CPU time... (I'm using sshguard)

[Paul Hartman]

On Mon, Mar 23, 2009 at 2:49 PM, Steve <gentoo_sjh@shic.co.uk> wrote:
> Steve wrote:
>>
>> Do others get this behaviour - is this a bug in syslog-ng?
>
> Sorry for the multiple posts... a slight error on my part.  The sshguard
> process wasn't running - a /bin/sh process trying to spawn it was running
> (there was no link from /usr/local... to the binary) and when the binary
> failed to execute - syslog-ng got itself into a tiz.  Everything seems to
> work fine when I correct the path to the program.
>
> Problem solved - but, I guess, this is a flaw in syslog-ng... I'd have hoped
> it would generate an error message rather than behave as it did.

I had a possibly similar problem a while back with syslog-ng going
crazy when a certain daemon would crash (in my case it filled up the
log wit about 60 gigabytes of the same thing repeated over and over,
in addition to using massive CPU%). I switched to metalog and haven't
had any problems since.