Re: s6 problems logging
On Sun, Jan 27, 2019 at 02:27:10PM -0500, Roger Pate wrote:
> On Sun, Jan 27, 2019 at 1:56 PM Sean MacLennan 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} p...@storpool.com
PGP key:http://people.FreeBSD.org/~roam/roam.key.asc
Key fingerprint 2EE7 A7A5 17FC 124C F115 C354 651E EFB0 2527 DF13
signature.asc
Description: PGP signature
Re: s6 problems logging
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 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.
Re: s6 problems logging
On Sun, Jan 27, 2019 at 1:56 PM Sean MacLennan 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
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
On Sun, Jan 27, 2019 at 11:47:51AM -0500, Sean MacLennan wrote: > On Sun, 27 Jan 2019 05:20:00 + > Colin Booth 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 eventlock 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
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
On Sun, 27 Jan 2019 05:20:00 + Colin Booth 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
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 s100 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
s6 problems logging
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 s100 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
