s6-log taking 100% CPU

s6-log taking 100% CPU

[Vallo Kallaste]

Hi

I have noticed that s6-log enters busyloop after failing to rotate
the log. Some data:

 * I don't have strace output at hand, but from memory it was
   infinite stream of identical poll() related lines.
 * s6-log runs as: s6-log -b s16777215 n25 S0 !xz -0q /var/service/nslcd/log
 * Happens only for service loggers missing the log/state file. Most
   service loggers do not have the log/state file, this is probably
   my mistake in some deployment script. 
 * There are following lines in s6-svscan log:

s6-log (processor child): fatal: unable to open_readb /var/service/nslcd/log/state: No such file or directory
s6-log: warning: processor failed in /var/service/nslcd/log

It seems that this is caused by my mistake but perhaps it could be
handled better?

BR,
-- 
Vallo

Re: s6-log taking 100% CPU

[Laurent Bercot]

> I have noticed that s6-log enters busyloop after failing to rotate
> the log. Some data:
> 
>  * I don't have strace output at hand, but from memory it was
>    infinite stream of identical poll() related lines.
>  * s6-log runs as: s6-log -b s16777215 n25 S0 !xz -0q /var/service/nslcd/log
>  * Happens only for service loggers missing the log/state file. Most
>    service loggers do not have the log/state file, this is probably
>    my mistake in some deployment script. 

 Good catch : you discovered two bugs at once ! They are clearly my
mistake, not yours.

 * s6-log should not fail to execute a processor when the state file is
missing: it should do as if there was an empty state file.
 * if the processor execution fails for some reason, s6-log should not
busyloop: it should use the cooldown timer defined by the "r" directive.

 Thanks for the report, I will work on a fix and prepare a new release.

-- 
 Laurent

Re: s6-log taking 100% CPU

[Laurent Bercot]

 * Actually, the first bug isn't one. The problem only shows up, as you
said, when the "state" file is missing, and I have verified that it can
only happen when users are manually tampering with logdirs and removing
the "state" file. This is a misuse of a logdir, and I'd rather have s6-log
complain in that case than silently working and producing unexpected
results, such as running a processor with an empty state file.

 * I cannot reproduce the second one. Works For Me (tm) : all processor
failure cases are correctly detected and by default a cooldown of 2 seconds
applies before processor execution is attempted again.
 Can you please send me your skalibs' sysdeps file ? Thank you.

-- 
 Laurent

Re: s6-log taking 100% CPU

[Laurent Bercot]

>  Can you please send me your skalibs' sysdeps file ? Thank you.

 Oh, and I would also like an output of "strace -f" on the s6-log process,
to see what happens with the first failing child process.
 Thank you.
 Sorry for the spam, list.

-- 
 Laurent

Re: s6-log taking 100% CPU

[Vallo Kallaste]

On Thu, Dec 13, 2012 at 04:19:25PM +0200, Vallo Kallaste
<kalts@estpak.ee> wrote:

> I have noticed that s6-log enters busyloop after failing to rotate
> the log. Some data:
> 
>  * I don't have strace output at hand, but from memory it was
>    infinite stream of identical poll() related lines.

I have reproduced it and here's the strace output:

poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
poll([{fd=0, events=0}, {fd=5, events=POLLIN|POLLHUP}, {fd=4, events=POLLOUT}], 3, -1) = 1 ([{fd=4, revents=POLLOUT}])
...
ad infinitum

BR,
-- 
Vallo