s6-log problem with +regex

s6-log problem with +regex

[Dewayne Geraghty]

Thank-you for s6-rc and friends.  I came across two items:
1. the s6-log in testing requires a control directive. In my testing
without a T, t, n $VALUE for example, the s6-log command failed.
2. The regular expression preceded by a + unintentionally matches
everything, which was surprising as I intended to maintain separate logs
 which emanated from the same process (apache24)

So to testing.  My test comprised an input /tmp/af with the intention of
four separate s6-log managed logdirs. The logdirs' structure was
correctly created, however three contained the same content, and the
default contained nothing.  So the reduced form of testing looks like this:
# cat /tmp/af   # a file of text to be processed
a line of text not selected
b nother line of text
c more lines
[date] with line of text

The intention is to create a separate log based on a regex of the first
character.  Unfortunately the selection mechanism failed and the entire
content of the test file (/tmp/af) was duplicated, ie unselectively.

The following places the content of /tmp/af into /tmp/date-only.

#!/usr/local/bin/execlineb -P ; # The testing script
redirfd -r 0 /tmp/af
/usr/local/bin/s6-log -b n3 +^\\\[ /tmp/date-only  f s100 S1500 T
/tmp/default

The following works correctly, in that date-only does not contain the
[date] line.  It does contain the rest of /tmp/af, while /tmp/default
does contain only the date (input line).

# cat s6-test.sh
#!/usr/local/bin/execlineb -P
redirfd -r 0 /tmp/af
/usr/local/bin/s6-log -b n3 -^\\\[ /tmp/date-only  f s100 S1500 T
/tmp/default

Incidentally using the s6-log command
/usr/local/bin/s6-log -b n3 +^\\\[ /tmp/date-only  s10 S150 T +^b
/tmp/b-only  f s100 S1500 T /tmp/default
results in both
/tmp/date-only/current and /tmp/b-only/current
containing all of /tmp/af, /tmp/default had the expected structure but
empty current file.

The platform is amd64 FreeBSD 11.2Stable built May 6, clang v7.0.0 and
clang 8.0.0

PS I haven't made sense of the hyphen in the example, after "E500 - " on
page https://www.skarnet.org/software/s6/s6-log.html.  Testing resulted in
s6-log: fatal: unrecognized directive: -

Re: s6-log problem with +regex

[Guillermo]

Hi,

El jue., 9 may. 2019 a las 22:03, Dewayne Geraghty escribió:
>
> My test comprised an input /tmp/af with the intention of
> four separate s6-log managed logdirs. The logdirs' structure was
> correctly created, however three contained the same content, and the
> default contained nothing.  So the reduced form of testing looks like this:
> # cat /tmp/af   # a file of text to be processed
> a line of text not selected
> b nother line of text
> c more lines
> [date] with line of text
>
> The intention is to create a separate log based on a regex of the first
> character.

Did you want something like this (in shell)?

/usr/local/bin/s6-log - +^a /tmp/a-only - +^b /tmp/b-only - +^c
/tmp/c-only - +^\\\[ /tmp/date-only - f /tmp/default </tmp/af

> The following places the content of /tmp/af into /tmp/date-only.
>
> #!/usr/local/bin/execlineb -P ; # The testing script
> redirfd -r 0 /tmp/af
> /usr/local/bin/s6-log -b n3 +^\\\[ /tmp/date-only  f s100 S1500 T
> /tmp/default

Yes, because at the beginning of directive processing, all input lines
are implicitly selected. Therefore, a '+' directive does nothing if
there aren't any '-' directives preceding it that deselect something:
anything it selects is already selected.

> The following works correctly, in that date-only does not contain the
> [date] line.  It does contain the rest of /tmp/af, while /tmp/default
> does contain only the date (input line).
>
> # cat s6-test.sh
> #!/usr/local/bin/execlineb -P
> redirfd -r 0 /tmp/af
> /usr/local/bin/s6-log -b n3 -^\\\[ /tmp/date-only  f s100 S1500 T
> /tmp/default

Yes, because at the beginning of directive processing, all input lines
are implicitly selected, and then the '-' directive deselects those
that start with '[', so /tmp/date-only contains everything except
those lines. The 'f' directive selects lines that start with '[',
because, quoting the documentation, those are the ones "that have not
yet been acted upon (i.e. that were always deselected when the script
encountered an action directive)", so /tmp/default contains only them.
The "action directive" that "acts upon" the other lines in this
context is '/tmp/date-only' (an automatically rotated logdir
directive).

> Incidentally using the s6-log command
> /usr/local/bin/s6-log -b n3 +^\\\[ /tmp/date-only  s10 S150 T +^b
> /tmp/b-only  f s100 S1500 T /tmp/default
> results in both
> /tmp/date-only/current and /tmp/b-only/current
> containing all of /tmp/af, /tmp/default had the expected structure but
> empty current file.

Yes, same as the first example. '+' directives that aren't preceded by
'-' directives that deselect something do nothing, therefore
/tmp/date-only and /tmp/b-only are copies of /tmp/af. And because
there are no lines "that have not yet been acted upon" (all of them
have been "acted upon" by the '/tmp/date-only' and '/tmp/b-only'
directives), the 'f' directive selects nothing and /tmp/default is
empty.

> PS I haven't made sense of the hyphen in the example, after "E500 - " on
> page https://www.skarnet.org/software/s6/s6-log.html.

It deselects all lines.

>  Testing resulted in
> s6-log: fatal: unrecognized directive: -

Oh? It works for me...

G.

Re: s6-log problem with +regex

[Laurent Bercot]

>Thank-you for s6-rc and friends.  I came across two items:
>1. the s6-log in testing requires a control directive. In my testing
>without a T, t, n $VALUE for example, the s6-log command failed.

"s6-log 1", which does nothing but send stdin straight through to
stdout, works for me on both Linux and FreeBSD. 1 is an action
directive. So, I cannot reproduce what you're reporting here.


>2. The regular expression preceded by a + unintentionally matches
>everything, which was surprising as I intended to maintain separate logs
>  which emanated from the same process (apache24)

I can absolutely reproduce what you're reporting here, but the
match is intentional. :) By default, every line is selected; if you
want to do a positive matching, you have to first deselect everything:

>#!/usr/local/bin/execlineb -P ; # The testing script
>redirfd -r 0 /tmp/af
>/usr/local/bin/s6-log -b n3 +^\\\[ /tmp/date-only  f s100 S1500 T
>/tmp/default

Your +^\[ regular expression does nothing here because every line
is already selected, so everything goes into /tmp/default.
A "-" directive before the "+^\\\[" directive should deselect
every line, and then your matching expression will work as you
intend.


>The platform is amd64 FreeBSD 11.2Stable built May 6, clang v7.0.0 and
>clang 8.0.0

That is not a factor in the problem above. However, it *is* a factor
in the following issue:

>PS I haven't made sense of the hyphen in the example, after "E500 - " on
>page https://www.skarnet.org/software/s6/s6-log.html.  Testing resulted in
>s6-log: fatal: unrecognized directive: -

Now that is interesting. It appears that the BSD libc's regcomp()
does not support empty regular expressions: the directive "-" fails
with that error message on FreeBSD, OpenBSD and NetBSD. Whereas on
Linux (with either musl or glibc), an empty regular expression is
accepted by regcomp() and treated as always matching.

So, you found a portability problem; thanks for the report. I will
patch s6-log so that an empty regular expression is recognized even
on the BSDs - so "-" will always deselect everything and "+" will
always select everything.

In the meantime, on Free/Open/NetBSD (and likely Darwin too),
please use "-.*" as a way to deselect every line at the beginning
of a s6-log script.

--
Laurent

Re: s6-log problem with +regex

[Dewayne Geraghty]

Thank-you Guillermo & Laurent.  I appreciate the detail, being a virgin
to daemontools this is a steep learning curve as I'm trying to ween off
monit.

The solution works nicely (& as intended) when using the workaround regex:

redirfd -r 0 /tmp/af
/usr/local/bin/s6-log n3 -.* +^a /tmp/a-only -.* +^b /tmp/b-only  -.*
+^c /tmp/c-only -.* +^\\\[ /tmp/date-only f /tmp/default

However without any control directive, the result is:
s6-log: usage: s6-log [ -d notif ] [ -q | -v ] [ -b ] [ -p ] [ -t ] [ -e
] [ -l linelimit ] logging_script

Though running s6-log without a control directive is probably a little
silly, perhaps the requirement to have one may be worthwhile mentioning
in the doc.

Aside: I had orginally placed
ErrorLog "|/usr/local/bin/s6-log -b n32 s50000 S7000000
/var/log/httpd-error T !'/usr/bin/xz -7q' /var/log/httpd-error"
into apache24 which worked well in testing (one httpd), but of course in
production there are lots of httpd that do NOT use the parent for
logging errors, so locking is a problem.

Because I have three websites (3x error files, 3x access files) I was
looking at using 6 pipelines into two s6-log processes and regex's to
route the content. (hence my original example).  Is this a good use of
resources or better to pipeline (funnel) to their own s6-log?

Kind regards, Dewayne.

Re: s6-log problem with +regex

[Laurent Bercot]

>However without any control directive, the result is:
>s6-log: usage: s6-log [ -d notif ] [ -q | -v ] [ -b ] [ -p ] [ -t ] [ -e
>] [ -l linelimit ] logging_script
>
>Though running s6-log without a control directive is probably a little
>silly, perhaps the requirement to have one may be worthwhile mentioning
>in the doc.

  Again, I cannot reproduce that, either on Linux or on FreeBSD.
Running s6-log without a control directive works as intended for me.
Can you please paste the exact command line you're running that causes
the issue for you ?


>Aside: I had orginally placed
>ErrorLog "|/usr/local/bin/s6-log -b n32 s50000 S7000000
>/var/log/httpd-error T !'/usr/bin/xz -7q' /var/log/httpd-error"
>into apache24 which worked well in testing (one httpd), but of course in
>production there are lots of httpd that do NOT use the parent for
>logging errors, so locking is a problem.

Locking won't be a problem unless your services are logging lines
that are longer than (at least) 4 kB. For lines that are shorter than
4 kB, writing/reading a line through a pipe will be done atomically.
In a normal Apache logging configuration, lines won't be too long,
so you'll be fine.


>Because I have three websites (3x error files, 3x access files) I was
>looking at using 6 pipelines into two s6-log processes and regex's to
>route the content. (hence my original example).  Is this a good use of
>resources or better to pipeline (funnel) to their own s6-log?

  It's entirely your choice. The s6-log process doesn't take a lot of
resources on its own, so my default choice would be to use a s6-log
process per log stream - because it's always easier to merge logs
than it is to separate them. If your priority is to use the least
amount of CPU, or if you're not sure, definitely use more s6-log
processes and less regex matching. But if your priority is to use as
little RAM as possible, you'll probably get slightly better results
by funneling several log streams into one s6-log process and using
some regex matching. I have not profiled this, though.

--
  Laurent