Sometimes multilog rotates the logfile when receiving a sigterm

[Rodrigo Campos-6]

I'm using multilog (running <program> | multilog...) with a program
that sometimes segfaults or that someone does a kill <program pid>.

Also, I'm seeing that the logs are rotated without getting to the size
specified, and an ALRM signal is never sent to it.

I've made a simple test case to see this and when I kill it, it
sometimes rotates the log. I've made a simple asd.sh script: cat
asd.sh

echo "una frase"
echo $$
sleep 25


And I run "sh asd.sh | multilog s1048576 ./test/".

If I kill it using ctrl+c or just "kill <pid>" it sometimes rotates
the file (besides its way low the size it should be).


Does anyone know how to avoid this or if it is possible to avoid it ?
Perhaps this is on purpose ?





Thanks a lot,
Rodrigo

[Daryl Tester-3]

(* Reply to /dev/null'd *)

Rodrigo Campos wrote:

> Also, I'm seeing that the logs are rotated without getting to the size
> specified, and an ALRM signal is never sent to it.

Are the logs rotated to *.s files with 744 permissions, or *.u files with
644 permissions?  What are the permissions on ./test/current when multilog
has "terminated"?

> If I kill it using ctrl+c or just "kill <pid>" it sometimes rotates
> the file (besides its way low the size it should be).

Depending on your shell, ^C goes to the process group, so multilog will
receive a SIGINT which I don't believe it traps (and therefore would
terminate abnormally).  I don't know about your "kill", except that if
multilog terminated abnormally previously (denoted by the permissions on
current) it will rotate current to a *.u filename when multilog runs the
next time.

> Does anyone know how to avoid this or if it is possible to avoid it ?

multilog isn't traditionally run from the command line.  If you
honestly have a requirement to do this, run something that will
run a setpgrp() prior to running multilog so that it shouldn't
receive signals sent to the process group and should therefore
terminate normally when the pipe closes.


--
Regards,
  Daryl Tester

"Crush! Kill! Deploy!"  -- Lost In Space I.T. Dept.

[Rodrigo Campos-6]

2009/8/28 Daryl Tester <dt-djb@...>:
> (* Reply to /dev/null'd *)
>
> Rodrigo Campos wrote:
>
>> Also, I'm seeing that the logs are rotated without getting to the size
>> specified, and an ALRM signal is never sent to it.
>
> Are the logs rotated to *.s files with 744 permissions, or *.u files with
> 644 permissions?

.u files with 644

>  What are the permissions on ./test/current when multilog
> has "terminated"?

On the directory ? drwx------

>
>> If I kill it using ctrl+c or just "kill <pid>" it sometimes rotates
>> the file (besides its way low the size it should be).
>
> Depending on your shell, ^C goes to the process group, so multilog will
> receive a SIGINT which I don't believe it traps (and therefore would
> terminate abnormally).  I don't know about your "kill", except that if
> multilog terminated abnormally previously (denoted by the permissions on
> current) it will rotate current to a *.u filename when multilog runs the
> next time.

I see the file rotated without running it a next time. Could this be
caused be something else ?


>
>> Does anyone know how to avoid this or if it is possible to avoid it ?
>
> multilog isn't traditionally run from the command line.  If you
> honestly have a requirement to do this, run something that will
> run a setpgrp() prior to running multilog so that it shouldn't
> receive signals sent to the process group and should therefore
> terminate normally when the pipe closes.

But if I do "kill <pid>" where pid is the pid of the program, it
should not affect multilog, shouldn't it ? Also it should not matter
if the program segfaults ? or that perhaps could affect it ?





Thanks a lot,
Rodrigo

[Daryl Tester-3]

(* Reply to /dev/null'd *)

Rodrigo Campos wrote:

>> Are the logs rotated to *.s files with 744 permissions, or *.u files with
>> 644 permissions?

> .u files with 644

This indicates that multilog had been abnormally terminated.

>>  What are the permissions on ./test/current when multilog
>> has "terminated"?

> On the directory ? drwx------

./test/current is a file.  It should be 744 when multilog has cleanly
exited, or 644 while multilog is running or has been abnormally
terminated.

From <http://cr.yp.to/daemontools/multilog.html>:

While multilog is running, current has mode 644. If multilog sees the
end of stdin, it writes current safely to disk, and sets the mode of
current to 744. When it restarts, it sets the mode of current back to
644 and continues writing new lines.

And:

* .s: This file is completely processed and safely written to disk.
* .u: This file was being created at the moment of an outage. It may
have been truncated. It has not been processed.

> I see the file rotated without running it a next time.

Rotate to *.s, or *.u.  There is a race here - if the first program
terminates quickly enough and closes the pipe, multilog may get
the chance to clean up before receiving the signal.

> Could this be caused be something else ?

Perhaps, but you're going to need to observe the state of the files
prior to running multilog again.  I'd wager that what you're seeing
is lot of multilog cleaning up the previous run.

> But if I do "kill <pid>" where pid is the pid of the program, it
> should not affect multilog, shouldn't it ?

Yes, it might.  As I wrote previously:

>> I don't know about your "kill", except that if
>> multilog terminated abnormally previously (denoted by the permissions on
>> current) it will rotate current to a *.u filename when multilog runs the
>> next time.


--
Regards,
  Daryl Tester

"Crush! Kill! Deploy!"  -- Lost In Space I.T. Dept.

[Rodrigo Campos-6]

2009/8/28 Daryl Tester <dt-djb@...>:

> (* Reply to /dev/null'd *)
>
> Rodrigo Campos wrote:
>
>>> Are the logs rotated to *.s files with 744 permissions, or *.u files with
>>> 644 permissions?
>
>> .u files with 644
>
> This indicates that multilog had been abnormally terminated.

Yeap

>>
>> I see the file rotated without running it a next time.
>
> Rotate to *.s, or *.u.  There is a race here - if the first program
> terminates quickly enough and closes the pipe, multilog may get
> the chance to clean up before receiving the signal.

hmm, could be.


Anyways, I've tried sending a SIGPIPE to multilog (what multilog
should receive if the process die, if I'm not wrong) and it happens
that the file is rotated with .u extension (and without running it an
other time).

I've thought that perhaps it should handle SIGPIPE as a SIGTERM, I
made a patch at work, but... it was friday, I didn't test it and... go
home :). What do you think about handling SIGPIPE as a SIGTERM ?




Thanks a lot,
Rodrigo

[Daryl Tester-3]

(* Reply to /dev/null'd *)

Rodrigo Campos wrote:

>> Rotate to *.s, or *.u.  There is a race here - if the first program
>> terminates quickly enough and closes the pipe, multilog may get
>> the chance to clean up before receiving the signal.

> hmm, could be.

Well, it took me several runs before I saw the results you did.
Without intensive observation, I'm putting it down to races.

> Anyways, I've tried sending a SIGPIPE to multilog (what multilog
> should receive if the process die, if I'm not wrong)

If you mean the first process, no.  If the pipe is closed due to
the write process exiting (either normally or abnormally) then
multilog will receive EOF when attempting to read from the pipe.
SIGPIPE is received by the writing process when attempting to
write to the pipe when the *reader* has gone away.

> and it happens that the file is rotated with .u extension (and
> without running it an other time).

$ mkdir TEST1
$ (sleep 1; ls -l TEST1 >&2; sleep 40) | multilog ./TEST1
# Note: multilog is still running at this point
total 0
-rw-r--r--  1 dt  wheel  0 Aug 29 17:47 current
-rw-------  1 dt  wheel  0 Aug 29 17:47 lock
-rw-r--r--  1 dt  wheel  0 Aug 29 17:47 state
^C
$ ls -l TEST1
total 0
-rw-r--r--  1 dt  wheel  0 Aug 29 17:47 current
-rw-------  1 dt  wheel  0 Aug 29 17:47 lock
-rw-r--r--  1 dt  wheel  0 Aug 29 17:47 state

$ (sleep 1; ls -l TEST1 >&2; sleep 40) | multilog ./TEST1
# Note: Multilog has rotated current to *.u due to funky current perms
total 0
-rw-r--r--  1 dt  wheel  0 Aug 29 17:47 @400000004a98e5cd368417c4.u
-rw-r--r--  1 dt  wheel  0 Aug 29 17:54 current
-rw-------  1 dt  wheel  0 Aug 29 17:47 lock
-rw-r--r--  1 dt  wheel  0 Aug 29 17:54 state

# Wait until multilog has terminated
$ ls -l TEST1
total 0
-rw-r--r--  1 dt  wheel  0 Aug 29 17:47 @400000004a98e5cd368417c4.u
-rwxr--r--  1 dt  wheel  0 Aug 29 17:54 current
-rw-------  1 dt  wheel  0 Aug 29 17:47 lock
-rw-r--r--  1 dt  wheel  0 Aug 29 17:54 state

current's permissions show that multilog has terminated normally.

If you're getting different results, then you need to show what
steps you are performing to get those results.

> I've thought that perhaps it should handle SIGPIPE as a SIGTERM, I
> made a patch at work, but... it was friday, I didn't test it and... go
> home :). What do you think about handling SIGPIPE as a SIGTERM ?

See above regarding signals.  

Again, remember that you're running multilog from the command line,
which *isn't how it's normally run*, so you're seeing and trying to
correct behaviour that would normally not be an issue.  multilog
typically runs under supervise, which never randomly sends SIGINT
to its child processes.

Personally, if I were to write something to work around this behaviour
I would write a nohup-style wrapper that blocks SIGHUP or performs a
setsid() before exec'ing multilog (ala "Bernstein chaining"), or if
you're running under Linux possibly use the setsid command (I've not
tried this as I don't have a daemontools environment under Linux to
test, and my setsid here appears to be doing an undocumented fork()
as well).


--
Regards,
  Daryl Tester

"Crush! Kill! Deploy!"  -- Lost In Space I.T. Dept.

[Rodrigo Campos-6]

2009/8/29 Daryl Tester <dt-djb@...>:

> (* Reply to /dev/null'd *)
>
> Rodrigo Campos wrote:
>
>>> Rotate to *.s, or *.u.  There is a race here - if the first program
>>> terminates quickly enough and closes the pipe, multilog may get
>>> the chance to clean up before receiving the signal.
>
>> hmm, could be.
>
> Well, it took me several runs before I saw the results you did.
> Without intensive observation, I'm putting it down to races.
>
>> Anyways, I've tried sending a SIGPIPE to multilog (what multilog
>> should receive if the process die, if I'm not wrong)
>
> If you mean the first process, no.  If the pipe is closed due to
> the write process exiting (either normally or abnormally) then
> multilog will receive EOF when attempting to read from the pipe.
> SIGPIPE is received by the writing process when attempting to
> write to the pipe when the *reader* has gone away.

Yes, you are right. Sorry

>
>> and it happens that the file is rotated with .u extension (and
>> without running it an other time).
>
> $ mkdir TEST1
> $ (sleep 1; ls -l TEST1 >&2; sleep 40) | multilog ./TEST1
> # Note: multilog is still running at this point
> total 0
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:47 current
> -rw-------  1 dt  wheel  0 Aug 29 17:47 lock
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:47 state
> ^C
> $ ls -l TEST1
> total 0
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:47 current
> -rw-------  1 dt  wheel  0 Aug 29 17:47 lock
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:47 state
>
> $ (sleep 1; ls -l TEST1 >&2; sleep 40) | multilog ./TEST1
> # Note: Multilog has rotated current to *.u due to funky current perms
> total 0
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:47 @400000004a98e5cd368417c4.u
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:54 current
> -rw-------  1 dt  wheel  0 Aug 29 17:47 lock
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:54 state
>
> # Wait until multilog has terminated
> $ ls -l TEST1
> total 0
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:47 @400000004a98e5cd368417c4.u
> -rwxr--r--  1 dt  wheel  0 Aug 29 17:54 current
> -rw-------  1 dt  wheel  0 Aug 29 17:47 lock
> -rw-r--r--  1 dt  wheel  0 Aug 29 17:54 state
>
> current's permissions show that multilog has terminated normally.
>
> If you're getting different results, then you need to show what
> steps you are performing to get those results.

No I'm getting the same results in my machine too

>
>> I've thought that perhaps it should handle SIGPIPE as a SIGTERM, I
>> made a patch at work, but... it was friday, I didn't test it and... go
>> home :). What do you think about handling SIGPIPE as a SIGTERM ?
>
> See above regarding signals.

Yes, Thanks :)

> Again, remember that you're running multilog from the command line,
> which *isn't how it's normally run*, so you're seeing and trying to
> correct behaviour that would normally not be an issue.  multilog
> typically runs under supervise, which never randomly sends SIGINT
> to its child processes.

Ahh, I understand.

It happens on some machine I do not have access right now, I will
investigate further if any signal its getting to multilog or something
like that.

>
> Personally, if I were to write something to work around this behaviour
> I would write a nohup-style wrapper that blocks SIGHUP or performs a

Yes, perhaps running "<program> | (trap ...; multilog...)" makes the
trick (nohup if that is the signal, but trap if its other signal).
Will try something like that, thanks :)

Or perhaps I can always send a SIGTERM to multilog first and then
SIGTERM to the program. Although avoiding the signals to arrive to
multilog seems to be what I really want (if that is what is causing it
to generate the .u files I'm seeing).

An other option perhaps is running it through a fifo (mkfifo).

Next week I will have access to the machines again, investigate
further what is happening and let you know =)




Thanks a lot,
Rodrigo

[Daryl Tester-3]

(* Reply to /dev/null'd *)

Rodrigo Campos wrote:

>> If you mean the first process, no.

...

> Yes, you are right. Sorry

You don't have to apologise - if you're learning anything from this,
then it's good.  :-)

>> Personally, if I were to write something to work around this behaviour
>> I would write a nohup-style wrapper that blocks SIGHUP or performs a

> Yes, perhaps running "<program> | (trap ...; multilog...)" makes the
> trick

That should do it, provided that using a subshell doesn't introduce
any other issues (i.e. it's not preferred under if daemontools because
supervise would send the signal to the shell, and not the multilog
process under it).  If you're not running multilog under daemontools
then it should be fine.

> (nohup if that is the signal, but trap if its other signal).

That takes me back - "in the old days" nohup was just a shell script
that did exactly that - trapped SIGUP, exec'd the remainder of its
arguments.

Actually, this shows the problem nicely ...

$ (trap "echo bing >&2" SIGINT; sleep 20; echo hi) | (trap "echo bong" SIGINT; read x)
^C
bong
bing
$

Both processes either end of the pipe received SIGINT.

> Or perhaps I can always send a SIGTERM to multilog first and then
> SIGTERM to the program.

Probably not - if the first process writes any terminating message
then it will be lost as a) multilog is no longer running, and b)
the first process will get SIGPIPE'd because the pipe no longer has
a reader (multilog) (which may, depending on how it handles SIGPIPE
cause its termination to take a different direction).  The preferred
order is to terminate the first process only, and when it exits the
pipe will be closed down causing multilog to exit cleanly.

> Although avoiding the signals to arrive to
> multilog seems to be what I really want (if that is what is causing it
> to generate the .u files I'm seeing).

Remember that this is behaviour is most likely caused by your
*interactive* shell.  A shell spawned out of crontab or start
script is very unlikely to send a signal to a process *group*
(or see ^C from a controlling tty).  If your final environment
is running multilog non-interactively then you're unlikely to
see any of the behaviour you're trying to avoid here.

> An other option perhaps is running it through a fifo (mkfifo).

Potentially, but it shouldn't be necessary.  It depends on when
you start multilog if your shell will put it into it's own
process group separate from the pipe writer (I think it should,
otherwise issuing ^C would cause all the processes you've
started to get SIGINT, which doesn't sound like a fun plan.
But I've not tested this).

--
Regards,
  Daryl Tester

"Crush! Kill! Deploy!"  -- Lost In Space I.T. Dept.

[Rodrigo Campos-6]

2009/8/30 Daryl Tester <dt-djb@...>:

> (* Reply to /dev/null'd *)
>
> Rodrigo Campos wrote:
>
>>> If you mean the first process, no.
>
> ...
>
>> Yes, you are right. Sorry
>
> You don't have to apologise - if you're learning anything from this,
> then it's good.  :-)

=)

>> Although avoiding the signals to arrive to
>> multilog seems to be what I really want (if that is what is causing it
>> to generate the .u files I'm seeing).
>
> Remember that this is behaviour is most likely caused by your *interactive*
> shell.  A shell spawned out of crontab or start
> script is very unlikely to send a signal to a process *group*
> (or see ^C from a controlling tty).  If your final environment
> is running multilog non-interactively then you're unlikely to
> see any of the behaviour you're trying to avoid here.

Well, it was started from a "start script", have no tty attached and
it *shouldn't* be interactive. But it seems in QNX 6.3.2 /bin/sh is a
ksh by default and it runs in interactive mode no matters what
(although then I found the +i option, but I didn't try it)

I just changed it to bash and that made the trick (since it didn't run
in interactive mode). Although I don't fully understand how this
solved it, since the signal that was sent to the process was a SIGTERM
(in the "production" environment, not in my simple tests)


Anyways, it seems to be solved :)





Thanks a lot for your help,

Rodrigo