s6 problems logging

s6 problems logging

[Sean MacLennan]

I have a service called doorknob that I want to log the output of. Here
is the run file:

#!/command/execlineb -P
/usr/sbin/doorknob -fs

The -f keeps doorknob in the foreground and the -s sends all messages
to stdout.

The log/run file is:

#!/command/execlineb -P
s6-log -b n20 s1000000 t .

My understanding is that the stdout should go to s6-log and be put in
log/current. But nothing seems to be logged.

Cheers,
   Sean

https://github.com/smaclennan/doorknob

Re: s6 problems logging

[Colin Booth]

On Sat, Jan 26, 2019 at 10:15:17PM -0500, Sean MacLennan wrote:
> I have a service called doorknob that I want to log the output of. Here
> is the run file:
> 
> #!/command/execlineb -P
> /usr/sbin/doorknob -fs
> 
> The -f keeps doorknob in the foreground and the -s sends all messages
> to stdout.
> 
> The log/run file is:
> 
> #!/command/execlineb -P
> s6-log -b n20 s1000000 t .
> 
> My understanding is that the stdout should go to s6-log and be put in
> log/current. But nothing seems to be logged.
> 
> Cheers,
>    Sean
> 
> https://github.com/smaclennan/doorknob
Everything looks fine from over here. Does running doorknob with -fs
from the terminal do what you expect? Also, what does 
`s6-svstat PATH_TO_DOORKNOB_SVCDIR' and 
`s6-svstat PATH_TO_DOORKNOB_SVCDIR/log' 
tell you? Also, does the target dir for s6-log have the files "current"
(apparently not), "lock", and "state"? Those final two files are created
by s6-log automatically and should at least indicate that it's starting
up fine.

Cheers!
-Colin

-- 
Colin Booth

Re: s6 problems logging

[Sean MacLennan]

On Sun, 27 Jan 2019 05:20:00 +0000
Colin Booth <colin@heliocat.net> wrote:

> Everything looks fine from over here. Does running doorknob with -fs
> from the terminal do what you expect? 

Yup, I get a log message to the console when I send an email.

> Also, what does 
> `s6-svstat PATH_TO_DOORKNOB_SVCDIR' and 
> `s6-svstat PATH_TO_DOORKNOB_SVCDIR/log' 
> tell you? 

/service/doorknob# /command/s6-svstat .
up (pid 948) 47861 seconds
/service/doorknob# /command/s6-svstat log
up (pid 847) 75815 seconds

Log has been up longer because I restarted doorknob with an s6-svc
down/up. Not sure if this is kosher with logging. Is there a
recommended way to start/stop services that have logging?

> Also, does the target dir for s6-log have the files
> "current" (apparently not), "lock", and "state"? Those final two
> files are created by s6-log automatically and should at least
> indicate that it's starting up fine.

/service/doorknob# ls log
current  event	lock  run  state  supervise

So it does have all the files/directories but current is empty even
though there should be some log entries.


I do use s6-log in one other service and it works. In the
service/s6-svscan-log I have:

#!/command/execlineb -P
cat ./fifo

And the same log/run as doorknob.

Cheers,
   Sean

Re: s6 problems logging

[Laurent Bercot]

>Yup, I get a log message to the console when I send an email.

Try stracing doorknob: "strace -v -s 256 /usr/sbin/doorknob -fs"
in your run script.
Check that the messages it's sending to its stdout are properly
terminated with a newline or null character.
(Messages sent to the console will appear even if they're not
terminated with a newline; but s6-log will keep them in the buffer
until it gets a terminator.)

Even if it's not the problem, strace may give you a hint of what
is happening. If it doesn't, pastebin it somewhere and give us the
link.

--
Laurent

Re: s6 problems logging

[Colin Booth]

On Sun, Jan 27, 2019 at 11:47:51AM -0500, Sean MacLennan wrote:
> On Sun, 27 Jan 2019 05:20:00 +0000
> Colin Booth <colin@heliocat.net> wrote:
> 
> > Everything looks fine from over here. Does running doorknob with -fs
> > from the terminal do what you expect? 
> 
> Yup, I get a log message to the console when I send an email.
>
> > Also, what does 
> > `s6-svstat PATH_TO_DOORKNOB_SVCDIR' and 
> > `s6-svstat PATH_TO_DOORKNOB_SVCDIR/log' 
> > tell you? 
> 
> /service/doorknob# /command/s6-svstat .
> up (pid 948) 47861 seconds
> /service/doorknob# /command/s6-svstat log
> up (pid 847) 75815 seconds
> 
> Log has been up longer because I restarted doorknob with an s6-svc
> down/up. Not sure if this is kosher with logging. Is there a
> recommended way to start/stop services that have logging?
> 
That should be fine. The only requirement that I know of is that you
re-register the service directory if you add or remove a log/ dir since
the presence or absence of a log/ directory is only checked when
s6-svscan first checks the directory. Reregistration in this case means:
delete the symlink, run s6-svscanctl -an, confirm that the removed
service has exited, create the symlink, and re-run s6-svscanctl -an.

Downing a logger may or may not cause problems, depending on how many
messages your service sends. Not because you'll lose stuff, but because
the service will block eventually as it tries to write to a pipe that
isn't being drained.
> > Also, does the target dir for s6-log have the files
> > "current" (apparently not), "lock", and "state"? Those final two
> > files are created by s6-log automatically and should at least
> > indicate that it's starting up fine.
> 
> /service/doorknob# ls log
> current  event	lock  run  state  supervise
> 
> So it does have all the files/directories but current is empty even
> though there should be some log entries.
> 
Cool, that means everything can write correctly.
> 
> I do use s6-log in one other service and it works. In the
> service/s6-svscan-log I have:
> 
> #!/command/execlineb -P
> cat ./fifo
> 
> And the same log/run as doorknob.
> 
> Cheers,
>    Sean
As Laurent mentioned, it sounds like your service isn't terminating its
lines correctly. The other option is that you're writing your messages
to stderr instead of stdout (in which case you'd end up on the
catch-all logger unless you did `fdmove -c 2 1' in your doorknob script 
before starting doorknob itself. That said, it's unlikely, since vprintf
seems to wite to stdout unless you tell it otherwise.

-- 
Colin Booth

Re: s6 problems logging

[Sean MacLennan]

So it seems that s6-log does not like buffered output. I modified
doorknob to vsnprintf into a buffer and then tried various output
methods.

1. puts(msg) Failed as expected (basically the same as vprintf).

2. write(1, msg, strlen(msg)) Worked! So non-buffered ok.

3. fputs(msg, stderr) Then add `fdmove -c 2 1' to the run file works!
   So fdmove seems to fix things up. Which is probably why most people
   don't see this problem.

Obviously, for 2 and 3 I did a strcat(msg, "\n").

So I think I will go with 2, but to stderr to follow Jonathan de Boyne
Pollard's comment "Unix conventions: Logs go to standard error".

Thanks everybody for the input. I probably would not have suspected the
buffered output was a problem.

Cheers,
   Sean

Re: s6 problems logging

[Roger Pate]

On Sun, Jan 27, 2019 at 1:56 PM Sean MacLennan <seanm@seanm.ca> wrote:
> So it seems that s6-log does not like buffered output. I modified
> doorknob to vsnprintf into a buffer and then tried various output
> methods.

s6-log (or another program) has no idea about your buffered output.
Output cannot be read until it has been written, and data still in a
buffer has not been written.  Change your program to flush after
messages.  It is common for stdio to buffer stdout differently
depending on whether it is a terminal and to not make that distinction
for stderr.  In your terminal, compare "doorknob -fs" (stdout as
terminal) to "doorknob -fs | cat" (stdout as pipe) to see the
difference.

PS. You have "dump" twice where I think you mean "dumb", in your
Github description and in your README.

Re: s6 problems logging

[Peter Pentchev]

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

On Sun, Jan 27, 2019 at 02:27:10PM -0500, Roger Pate wrote:
> On Sun, Jan 27, 2019 at 1:56 PM Sean MacLennan <seanm@seanm.ca> wrote:
> > So it seems that s6-log does not like buffered output. I modified
> > doorknob to vsnprintf into a buffer and then tried various output
> > methods.
> 
> s6-log (or another program) has no idea about your buffered output.
> Output cannot be read until it has been written, and data still in a
> buffer has not been written.  Change your program to flush after
> messages.  It is common for stdio to buffer stdout differently
> depending on whether it is a terminal and to not make that distinction
> for stderr.  In your terminal, compare "doorknob -fs" (stdout as
> terminal) to "doorknob -fs | cat" (stdout as pipe) to see the
> difference.

If it is not easy to change the program itself, the stdbuf(1)
utility in recent versions of coreutils might help (of course,
if you use some kind of minimal system, it may not always be
available).

G'luck,
Peter

-- 
Peter Pentchev  roam@{ringlet.net,debian.org,FreeBSD.org} pp@storpool.com
PGP key:        http://people.FreeBSD.org/~roam/roam.key.asc
Key fingerprint 2EE7 A7A5 17FC 124C F115  C354 651E EFB0 2527 DF13

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: s6 problems logging

[Jonathan de Boyne Pollard]

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

Peter Pentchev:

> If it is not easy to change the program itself, the stdbuf(1) utility 
> [...]
>
I am certain that M. MacLennan is capable of changing M. MacLennan's own 
program.  After all, you are replying to a message where xe said that xe 
already did.  (-:

Injecting things into the code of the running program via pre-loads 
should be a last resort, not on an equal footing with adjusting the 
program's logging.  In any case, the Bernstein |ptybandage| 
<http://jdebp.eu./Softwares/djbwares/bernstein-ptyget.html> achieves 
this /without/ injecting code into the target programs.

Re: s6 problems logging

[Guillermo]

Hello,

El dom., 27 ene. 2019 a las 15:56, Sean MacLennan escribió:
>
> So it seems that s6-log does not like buffered output.

It probably isn't that it doesn't like it, but that it doesn't even
get to see the output. As Jonathan also pointed out, when you run
doorknob using a supervision suite, stdout is redirected to a pipe,
which is not an 'interactive device' (unlike an interactive shell's
controlling terminal) so it is fully buffered. And at least GNU libc's
implementation of the <stdio.h> interface buffers indeed. A smaller
program that does your vprintf() + putchar('\n') sequence exhibits
this behaviour, and adding an fflush(stdout) call solves it. But...

> I modified
> doorknob to vsnprintf into a buffer and then tried various output
> methods.
>
> 1. puts(msg) Failed as expected (basically the same as vprintf).
>
> 2. write(1, msg, strlen(msg)) Worked! So non-buffered ok.
>
> 3. fputs(msg, stderr) Then add `fdmove -c 2 1' to the run file works!
>    So fdmove seems to fix things up. Which is probably why most people
>    don't see this problem.
>
> Obviously, for 2 and 3 I did a strcat(msg, "\n").
>
> So I think I will go with 2, but to stderr to follow Jonathan de Boyne
> Pollard's comment "Unix conventions: Logs go to standard error".

If you want minimal changes and follow the convention of logging to
stderr, you could have done vfprintf(stderr, fmt, ap) + fputc('\n',
stderr), which also works. stderr is never fully buffered.

G.

smaclennan/doorknob

[Jonathan de Boyne Pollard]

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

  *

    The plural of "address" is "addresses".  "-ii" is not how any word
    pluralizes in English.

  *

    The way to monitor such a directory nowadays is with
    |kevent(EVFILT_VNODE)| or |inotify_*()|.

  *

    Long-known multi-user spool security precautions: /Always/ check the
    |d_type|; /always/ |fstatat()|/|fstat()| the spool file and check
    for |S_ISREG()|.

  *

    Long-known multi-user spool security precautions: Spool areas should
    be beneath a non-world-accessible parent directory, and the program
    that dumps into the spool should be set-group-ID to a group (or a
    /non-owner/ user) that has search access on the parent in order to
    reach the spool directory beneath.  Not doing this is an error that
    was initially made in Postfix years ago, avoiding all set-ID
    programs without realizing that set-ID is a necessarymechanism for
    secure multi-user spooling when it is in this form. (See Bruce
    Guenter's bcron <http://untroubled.org/bcron/> for an example of an
    alternative way that multi-user spooling can be structured using a
    submission server and UCSPI-UNIX.)

    The spool-processing dæmon itself does not need to run under the
    aegis of this group, if it is simply started up already in its spool
    directory using |chdir|
    <http://jdebp.eu./Softwares/nosh/guide/commands/chdir.xml> (or cd
    <http://skarnet.org./software/execline/cd.html> or equivalent) in
    the |run| script.  (This also means that it does not need to
    hardcode the location of its spool directory.  Its spool directory
    is its working directory, where it works.)

  *

    Other security precautions: Dæmons such as this should /always/
    |setuidgid|
    <http://jdebp.eu./Softwares/nosh/guide/commands/setuidgid.xml> away
    from the superuser in their |run| scripts to an account dedicated to
    the dæmon.  (Compare the |run| script in Bruce Guenter's nullmailer
    <http://untroubled.org/nullmailer/>.)

      o

        Jonathan de Boyne Pollard (2019). "Limiting services: Running
        under the aegises of unprivileged user accounts
        <http://jdebp.eu./Softwares/nosh/guide/limiting-services.html#users>".
        /nosh Guide/. Softwares.

      o

        https://unix.stackexchange.com/questions/450251/

  *

    Other spool-processing dæmon security measures: The dedicated user
    account has no need to own /anything/, neither the spooled files nor
    the spool directory itself.  It needs only read+write+execute
    permission on the spool directory, and read permission on the spool
    files.  Having ownership permission as well permits compromised
    dæmons to change ACLs and permissions.

      o

        Jonathan de Boyne Pollard (2019). "Log service security:
        Dedicated log user accounts
        <http://jdebp.eu./Softwares/nosh/guide/log-service-security.html#users>"./nosh
        Guide/. Softwares.

  *

    Debian family operating system conventions:  That has not been the
    way to write a van Smoorenburg |rc| script for Debian family
    operating systems since 2014.

      o

        Petter Reinholdtsen (2014-02-09). init-d-script
        <https://manpages.debian.org/stretch/sysvinit-utils/init-d-script.5.en.html>.
        /File formats manual/. Debian.

  *

    C language standards: |stdout| is fully buffered if it is not an
    interactive device, which a pipe is indeed not. |stderr| is of
    course /not/ fully buffered.

  *

    Unix conventions: Logs go to standard error.

Re: smaclennan/doorknob

[Sean MacLennan]

On Sun, 27 Jan 2019 14:39:16 +0000
Jonathan de Boyne Pollard <J.deBoynePollard-newsgroups@NTLWorld.COM>
wrote:

> A lot of constructive comments on doorknob which I am not going to
> include here.

Well, I have updated doorknob to *hopefully* respond to all the
comments. I have pushed the changes to github if anybody is interested.

The big changes are moving the default location of the directories and
changing ownership.

Doorknob now has its own user. It basically does:

1. change to queue directory
2. setup inotify
3. drop privileges to doorknob user
4. read config
5. start handling messages

sendmail and mailq are now owned by the mail user and group
(configurable) and are +s.

The queues are now (by default):

chown mail.mail /var/spool/doorknob
chown mail.mail /var/spool/doorknob/queue
chown mail.mail /var/spool/doorknob/tmp
chmod 750 /var/spool/doorknob
chmod 777 /var/spool/doorknob/queue
chmod 700 /var/spool/doorknob/tmp

Everything is configurable. You can make the doorknob user root, the
mail user root, and everything is as before.

Comments welcome.

Cheers,
   Sean