ca catchall logger prefix log lines with service names?

ca catchall logger prefix log lines with service names?

[Ihor Antonov]

Hi,

I am trying to figure out if I can set up svscan catchall logger in such
a way that it prepends a service name to every log line, so that it can
be clear where the log came from.

I am trying to avoid s6-rc setup where I need to explicitly create a
matching logger service.

Today I do this:
        
        s6-svscan $S6_RC_DIR | s6-log -- t s16777216 n64 $HOME/.local/log/svscan

But creates a log file where all logs from all services are mixed up and
are impossible to distinguish. There is already a strange looking thing
prepended to every line (@400000006356da4b2cb3ba0a - a timestamp?), so
one might say we have already started doing structured logging.

Is it possible to somehow add add service name as a second field in the
log line?

Thanks

Ihor

Re: ca catchall logger prefix log lines with service names?

[Laurent Bercot]

>I am trying to figure out if I can set up svscan catchall logger in such
>a way that it prepends a service name to every log line, so that it can
>be clear where the log came from.
>
>I am trying to avoid s6-rc setup where I need to explicitly create a
>matching logger service.

  You are saying "I want to use s6 without adopting s6 idioms because
I'm used to the way other supervisors do things, even when they're
giant hacks." :)

  It's much easier to have one dedicated set of logs per service, and
merge them later if that's what you want, than to have one big blob of
logs and separate them later for analysis. In other words: "cat | sort"
is cheaper than a series of "grep".

  The catch-all logger is exactly what it says: a catch-all. It only
gets the logs that are not diverted; it's not supposed to get
*everything* - although it can, if that's what you want, but then as
you noticed you get everything as is: output from the services go
directly to the catch-all logger. There is no intermediary process
that can prepend your log lines with information, because the services
have their output directly plugged into the pipe to the catch-all 
logger.

  The only way to modify the log lines is to insert an additional
process between your service and the catch-all logger that performs
the modification. And the simplest way to achieve that is to have
a foo/log service (or a foo-log consumer, if you're using s6-rc) for
every foo producer, that processes its stdin and writes the modified
lines to stdout, something like

   s6-format-filter "foo: %s"

  But that's still defining a consumer for your service. There is,
unfortunately, no way to do that without a consumer for every service.
And if you're going to add consumers anyway, you may as well write
dedicated loggers directly instead of line processors that send
everything back to the catch-all logger.

  Note that it's not s6 being difficult; it's s6 being out of the way
by default, by not touching your logs. If another supervisor allows
you to modify log lines by default, it means it's inserting itself
between the service and its logger, which is terribly inefficient.


>But creates a log file where all logs from all services are mixed up and
>are impossible to distinguish. There is already a strange looking thing
>prepended to every line (@400000006356da4b2cb3ba0a - a timestamp?)

  Yes, it's a TAI64N timestamp. Process the file through s6-tai64nlocal
to get human-readable timestamps. One of the advantages of TAI64N stamps
is that they're alphabetically sorted, so you can merge several log
files into one via "cat log1 log2 log3... | sort".

--
  Laurent

Re: ca catchall logger prefix log lines with service names?

[Peter Shkenev]

Hello,

On Tue Oct 25, 2022 at 14:19 UTC, Ihor Antonov wrote:

> I am trying to figure out if I can set up svscan catchall logger in such
> a way that it prepends a service name to every log line, so that it can
> be clear where the log came from.

Service dirs are made for this. s6-log does not know the name of service
- it just writes data from stdin to log directory, appending timestamps
and handling rotation.

> I am trying to avoid s6-rc setup where I need to explicitly create a
> matching logger service.

Having logger per service is the intended pattern for s6/s6-rc. This
sets s6 logging framework apart from syslog and systemd-journald. s6
overview[1] and s6-log documentation[2] describes why logging is
designed this way.

And, again, s6-rc v1 and s6-frontend will make this easier. I am looking
forward for them too.

> Today I do this:
>
>         s6-svscan $S6_RC_DIR | s6-log -- t s16777216 n64 $HOME/.local/log/svscan

As Laurent stated in the previous thread, do not do that. s6-svscan is
not meant to be run in the terminal.

> @400000006356da4b2cb3ba0a - a timestamp?

Yes, this is a TAI64N timestamp. TAI64N is a reliable way to store
timestamps[3], since it does not have leap seconds and does not suffer
from problems like Y2K and Y2038. Also, these timestamps are easily
machine-readable.

If you want to read a log file with TAI64N timestamp, you can pipe it
through s6-tai64nlocal program:
    cat $LOGDIR/current | s6-tai64nlocal | less

Also, s6-log supports writing ISO 8601 timestamps, see s6-log
documentation[2] for details.

[1] https://skarnet.org/software/s6/overview.html
[2] https://skarnet.org/software/s6/s6-log.html
[3] http://skarnet.org/software/skalibs/libstddjb/tai.html

---
Best regards,
Peter