Re: A program that can get exactly the log of a supervised process?

Re: A program that can get exactly the log of a supervised process?

[Laurent Bercot]

>Any idea on how the log "teeing" may be done cleanly (and portably
>if possible; something akin to `tail -f' seems unsuitable because of
>potential log rotation), and perhaps any flaw or redundancy in the
>design above?

  The obstacle I have always bumped against when trying to do similar
things is that the teeing program always has to remain there, even
after it has done its job (it has read the readiness line and informed
the supervisor). And so, instead of "service | logger", your data
flow permanently becomes "service | loggrep | logger" before
readiness, and "service | cat | logger" after readiness (the best
loggrep can do is exec into cat, or reimplement its functionality,
once it has read its readiness line).

  That wouldn't be a huge performance problem, especially if "cat" can
do zero-copy data, but it is definitely a reliability problem:
  - loggrep must die when the service dies, so a new loggrep can be run
when the service runs again. So loggrep cannot be run as a separate
supervised service in the same service pipeline. (If loggrep were to
restart independently from service, it would need to check whether
service is ready, and run as 'cat' if it is. This is doable, but more
complex.)
  - That means that either the pipe between service and loggrep cannot
be held, or loggrep must have an additional notification that service
died. This is, again, doable, but more complex.
  - If loggrep isn't supervised, and the pipe isn't being held, then
killing loggrep will incur a broken pipe, which means a service restart
with a lost line of logs, which supervision aims to avoid.

  So basically, either loggrep is a simple tee-like program but you
weaken the supervision properties of the service, or the functionality
needs to be embedded in the supervision architecture, with loggrep
being a consumer for service and a producer for logger (which is
easy with s6-rc but not so much with pure s6) and loggrep always
watching the state of service (which is not so easy with s6-rc, where
you don't know the full path to another service directory).

  In short: practical issues. It's impossible to do that in a clean,
satisfying way.

  And it entirely makes sense that it's so difficult, because the very
idea is to use the *data flow* to inform the *control flow*, and that
is inherently dangerous and not planned for in supervision 
architectures.
Making your control flow depend on your data flow is not a good pattern
at all, and I really wish daemons would stop doing that.

  I'm sorry I don't have a better answer.

--
  Laurent

Re: A program that can get exactly the log of a supervised process?

[Casper Ti. Vector]

On Sun, Oct 24, 2021 at 06:20:53AM +0000, Laurent Bercot wrote:
>  So basically, either loggrep is a simple tee-like program but you
> weaken the supervision properties of the service, or the functionality
> needs to be embedded in the supervision architecture, with loggrep
> being a consumer for service and a producer for logger (which is
> easy with s6-rc but not so much with pure s6) and loggrep always
> watching the state of service (which is not so easy with s6-rc, where
> you don't know the full path to another service directory).

Well, I do realise the lifespan issue of the loggrep program, which is
why I asked the question in the first place.  But I really never thought
of directly inserting loggrep into the logging chain as a new node;
instead, what I have thought is making loggrep a program "attachable" to
the logger.  That is, the logger is extended with a listener which at
least one client can connect to, and which upon connection tees the log
to the client.  I do not know whether you have similar ideas.

Additionally, I have just noticed a race condition in the origin design
in my question.  If loggrep is double-forked by an external program
(execline or so), the daemon may become ready before loggrep is ready to
receive logs; a better way is to let loggrep do the double fork itself,
after the teeing pipe is ready.  The downside is that errors deemed
tolerable by the daemon but fatal by the user would then need to be
explicitly handled by loggrep; but this is probably already over-design,
so perhaps it just does not matter...

-- 
My current OpenPGP key:
RSA4096/0x227E8CAAB7AA186C (expires: 2022.09.20)
7077 7781 B859 5166 AE07 0286 227E 8CAA B7AA 186C

Re: A program that can get exactly the log of a supervised process?

[Laurent Bercot]

>Well, I do realise the lifespan issue of the loggrep program, which is
>why I asked the question in the first place.  But I really never thought
>of directly inserting loggrep into the logging chain as a new node;
>instead, what I have thought is making loggrep a program "attachable" to
>the logger.  That is, the logger is extended with a listener which at
>least one client can connect to, and which upon connection tees the log
>to the client.  I do not know whether you have similar ideas.

  Well in theory you could have something like skabus-dyntee
( https://skarnet.org/software/skabus/skabus-dyntee.html ) as your
logger, and have your "real" logger run as a skabus-dyntee client.
Then you could add a loggrep as a second skabus-dyntee client, and it
would just disappear when it has finished its work.

  It would be a little unreliable as is, because skabus-dyntee doesn't
care if it has no client at all, so if the real logger dies, it won't
block the log stream until the real logger has restarted, so you may
lose logs. But apart from that, it would work.

  A really reliable solution would be having a skabus-dyntee equivalent
that has one permanent output and blocks as long as that output isn't
there. As you say, it would be a logger extended with a listener.

  Another question is how to piggyback loggrep into the notification
mechanism: if loggrep is tied to the logger and not to the service,
it doesn't have native access to the notification pipe. That means a
specific mechanism is needed to give it cross-service access.

  That's definitely a lot of code and a lot of architectural
convolutions to accommodate what is ultimately a daemon misdesign.
But it's probably the least bad way to do it, so I might think about it
more and add something like that to s6 in the distant future.

--
  Laurent

Re: A program that can get exactly the log of a supervised process?

[Rio Liu]

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

Why not have the grepper listen on the log file directly? You'll need to have a timestamp in the log and know where the log is, but those can be known at the time of writing the service script.

--------原始郵件--------
在 2021年10月25日 08:37, Laurent Bercot 寫道：

>>Well, I do realise the lifespan issue of the loggrep program, which is
>>why I asked the question in the first place. But I really never thought
>>of directly inserting loggrep into the logging chain as a new node;
>>instead, what I have thought is making loggrep a program "attachable" to
>>the logger. That is, the logger is extended with a listener which at
>>least one client can connect to, and which upon connection tees the log
>>to the client. I do not know whether you have similar ideas.
>
> Well in theory you could have something like skabus-dyntee
> ( https://skarnet.org/software/skabus/skabus-dyntee.html ) as your
> logger, and have your "real" logger run as a skabus-dyntee client.
> Then you could add a loggrep as a second skabus-dyntee client, and it
> would just disappear when it has finished its work.
>
> It would be a little unreliable as is, because skabus-dyntee doesn't
> care if it has no client at all, so if the real logger dies, it won't
> block the log stream until the real logger has restarted, so you may
> lose logs. But apart from that, it would work.
>
> A really reliable solution would be having a skabus-dyntee equivalent
> that has one permanent output and blocks as long as that output isn't
> there. As you say, it would be a logger extended with a listener.
>
> Another question is how to piggyback loggrep into the notification
> mechanism: if loggrep is tied to the logger and not to the service,
> it doesn't have native access to the notification pipe. That means a
> specific mechanism is needed to give it cross-service access.
>
> That's definitely a lot of code and a lot of architectural
> convolutions to accommodate what is ultimately a daemon misdesign.
> But it's probably the least bad way to do it, so I might think about it
> more and add something like that to s6 in the distant future.
>
> --
> Laurent

Re: A program that can get exactly the log of a supervised process?

[Laurent Bercot]

>Why not have the grepper listen on the log file directly? You'll need to have a timestamp in the log and know where the log is, but those can be known at the time of writing the service script.

  There's no such thing as "the log file". There's the log backendS,
which can be one or more automatically rotated log files in a directory,
status files, network backends, etc.
  The only way to access the log stream in a reliable and generic way
is to read it on the way to the backends. You have no control over
what happens later on.

--
  Laurent

Re: A program that can get exactly the log of a supervised process?

[Casper Ti. Vector]

On Mon, Oct 25, 2021 at 12:37:41PM +0000, Laurent Bercot wrote:
> Another question is how to piggyback loggrep into the notification
> mechanism: if loggrep is tied to the logger and not to the service,
> it doesn't have native access to the notification pipe. That means a
> specific mechanism is needed to give it cross-service access.

As has been sketched in previous mails, make loggrep a double-forking
chainloader, where the grandparent blocks (before closing the
notification fd and then chaining) until the grandchild is ready to
accept logs (after connecting to the logger and spawning the "grep";
the latter perhaps being an awk script in most cases)?

> But it's probably the least bad way to do it, [...]

I fullly agree.  This is the crux of the problem.

-- 
My current OpenPGP key:
RSA4096/0x227E8CAAB7AA186C (expires: 2022.09.20)
7077 7781 B859 5166 AE07 0286 227E 8CAA B7AA 186C

A program that can get exactly the log of a supervised process?

[Casper Ti. Vector]

Many daemons output some lines in their logs (here assumed to have been
redirected to logging pipes in some supervision framework) that can be
used as a kind of markers for readiness.  So if we can implement the
following program, we will able to trivially add readiness support to
these daemons without patching their source code, while reducing the
daemon-specific code (the pattern recogniser) to a minimum:

* The program is double-forked from the ./run script of a service, and
  also watches for the death of the daemon: in case the daemon dies
  before logging the readiness marker (and optionally, if a specified
  timeout is reached), this program dies as well, killing its subprocess
  (the pattern recogniser, discussed below).  To maximise portability
  across supervision frameworks, the death notification can be
  implemented with a pipe that can be written to by an ancillary
  program ran from the ./finish script.

* The program somehow (directly or indirectly) gets a copy of the
  log from the reading side of the logging pipe, and feeds it into a
  specified pattern recogniser, which should exit 0 upon finding the
  readiness marker.  A special exit value of the subprocess can be
  considered a notification for fatal error erroneously ignored by the
  daemon, leading to the program exiting some special value which can
  be handled by a `s6-svc -t' invocation.  In order to avoid potential
  feedback loops, the subprocess should be killed (and waited for)
  before the program outputs any warning; the subprocess should be
  responsible for keeping itself quiet when running normally.

Any idea on how the log "teeing" may be done cleanly (and portably
if possible; something akin to `tail -f' seems unsuitable because of
potential log rotation), and perhaps any flaw or redundancy in the
design above?

-- 
My current OpenPGP key:
RSA4096/0x227E8CAAB7AA186C (expires: 2022.09.20)
7077 7781 B859 5166 AE07 0286 227E 8CAA B7AA 186C

Re: A program that can get exactly the log of a supervised process?

[Casper Ti. Vector]

On Sun, Oct 24, 2021 at 12:03:01AM +0800, Casper Ti. Vector wrote:
> Any idea on how the log "teeing" may be done cleanly (and portably
> if possible; something akin to `tail -f' seems unsuitable because of
> potential log rotation), and perhaps any flaw or redundancy in the
> design above?

The recordio program is extremely enlightening here:

* Instead of trying to communicate with the logger, our program can
  directly sit between the service and the logging pipe.
  (This also solves the lifespan issue cleanly, saving lots of code;
  the latter is apart from the lots of code to talk with the logger.)

* When forking, we may let the parent (instead of the child) exec()s
  into the service, so our program does not need to forward signals.
  (But the loggrep subprocess from our program may die after the
  supervisor receives SIGCHLD from the service; therefore in order
  not to interfere with the next run of the service, we should ensure
  the loggrep program would exit on EOF and does not produce spurious
  outputs on its stdout.)

The source code of the program, logtee (licence: CC0), is available at:
<https://cpaste.org/?fa30831511a456b7=#ECwUd1YaVQBLUokynQbRYZq5wvBvXXeXo3bQoeL2rL4L>
It may be tested with (logtee is itself init-agnostic; writing an
adapter to, for instance, s6, should be an easy exercise in the
manipulation of argv):

------------------------------------------------------------------------
#!/bin/execlineb -P
fdmove -c 3 1
logtee {
  fdmove 1 3 
  if { timeout 3 grep -q "bytes from" }
  echo
}
fdclose 3
fdmove -c 2 1
ping -i 10 example.com
------------------------------------------------------------------------

-- 
My current OpenPGP key:
RSA4096/0x227E8CAAB7AA186C (expires: 2024.09.30)
7077 7781 B859 5166 AE07 0286 227E 8CAA B7AA 186C

Re: A program that can get exactly the log of a supervised process?

[Casper Ti. Vector]

On Fri, Jun 23, 2023 at 01:44:19AM +0800, Casper Ti. Vector wrote:
> The source code of the program, logtee (licence: CC0), is available at:
> <https://cpaste.org/?fa30831511a456b7=#ECwUd1YaVQBLUokynQbRYZq5wvBvXXeXo3bQoeL2rL4L>

Sorry, patch (the first hunk is cosmetic):

--- logtee.c	2023-06-23 03:33:57.233531347 +0800
+++ logtee.c	2023-06-23 03:33:05.693672295 +0800
@@ -29,7 +29,7 @@
     *len = 0; return 1;
   }
   if (iopause_g (x, 2 - !x[1].fd, 0) < 0) strerr_diefu1sys (111, "iopause_g");
-  for (i = 0; i < 2; ++i) if (x[i].fd && x[i].revents) {
+  for (i = 0; i < 2; ++i) if (x[i].fd > 0 && x[i].revents) {
     r = fd_write (x[i].fd, buf + pos[i], *len - pos[i]);
     if (r < 0) {
       if (!i) return 0;
@@ -57,8 +57,9 @@
 int main (int argc, char const **argv, char const *const *envp) {
   int pir[2], fdc, fdw, argc1;
   PROG = "logtee"; ++argv; --argc;
-  if ((argc1 = el_semicolon (argv)) >= argc)
-    { strerr_dief1x (100, "unterminated block"); }
+  argc1 = el_semicolon (argv);
+  if (argc1 >= argc) strerr_dief1x (100, "unterminated block");
+  if (!argv[0] || !argv[argc1 + 1]) strerr_dief1x (100, "empty program");
   argv[argc1] = 0;
   if (pipe (pir) < 0) strerr_diefu1sys (111, "pipe");
   if ((fdc = selfpipe_init ()) < 0) strerr_diefu1sys (111, "selfpipe_init");

-- 
My current OpenPGP key:
RSA4096/0x227E8CAAB7AA186C (expires: 2024.09.30)
7077 7781 B859 5166 AE07 0286 227E 8CAA B7AA 186C

Re: A program that can get exactly the log of a supervised process?

[Casper Ti. Vector]

On Fri, Jun 23, 2023 at 03:39:39AM +0800, Casper Ti. Vector wrote:
> +  if (!argv[0] || !argv[argc1 + 1]) strerr_dief1x (100, "empty program");
>    argv[argc1] = 0;

Well, these two lines should be swapped.  Sorry for the spam :(

-- 
My current OpenPGP key:
RSA4096/0x227E8CAAB7AA186C (expires: 2024.09.30)
7077 7781 B859 5166 AE07 0286 227E 8CAA B7AA 186C