tini message are not flushed from stdout/stderr buffer until it die with the container

[CyrilDevOps]

the Spawned child process ... and Main child existed appears at the end of our container logs because they aren't flushed from stdout buffer.
after the fprintf \n, an fflush command need to be added to force the buffer to be flushed.

[krallin]

Interesting. Those logs actually go to stderr, not stdout, and they have trailing newlines, so even if stderr were line-buffered, flushing shouldn't be necessary. Any chance you have something like stdbuf in the path to starting Tini that might be configuring the streams differently? https://linux.die.net/man/1/stdbuf

[CyrilDevOps]

sorry for the delay for this answer,
we use tini with '-v' to get the spawn/exist status message.

with a dockerfile configured with tini v0.19.0 :
ENTRYPOINT ["/tini", "-v", "--"]
CMD ["/opt/ls.sh"]

ls.sh is just a dummy bash script :
#!/bin/bash

ls

exit 123

When I build and run the docker image, I get :
ls.sh
[INFO tini (1)] Spawned child process '/opt/ls.sh' with pid '7'
[INFO tini (1)] Main child exited normally (with status '123')

The INFO text show after the the 'ls.sh' result.
We were expecting :
[INFO tini (1)] Spawned child process '/opt/ls.sh' with pid '7'
ls.sh
[INFO tini (1)] Main child exited normally (with status '123')

[yosifkit]

It's likely not tini's fault; stdout/stderr ordering is hard. Like this issue in Docker itself: moby/moby#26986 moby/moby#31706

[CyrilDevOps]

Thanks.
docker and logs ordering doesn't seems to be a 'new' problem.
You can close this issue, I don't think there is any 'trick' tini can do.

[pt9999]

To set stdout and stderr as unbuffered, call setbuf(stdout, NULL) and setbuf(stderr, NULL).
https://man7.org/linux/man-pages/man3/setbuf.3.html

[igor-borovkov]

@krallin Hi Thomas! You think it would be possible to switch stdout to line buffering?

By default the stdout buffer in libc is around 4k whereas stderr is unbuffered by default. By the time I have tini "child segmentation fault" log output in the docker log, my main app (child process) already restarted and printed a ton of logging. Would be nice to see child segmentation fault log line right when it happened aligned with the log output of the main process and its error messages (tini prints "child exits with signal" to stdout - info/debug logging not stderr - which is fine, not all exits with a signal are abnormal - sigterm due to docker restart). Switching stdout to linebuffering won't hurt performance since tini barely does any logging even with -vv

setlinebuf(stdout); the first line in main()

[lbogdan]

@krallin As @igor-borovkov mentioned (thanks for digging out that info!), adding setlinebuf(stdout); at the beginning of main() fixes this.

Should I open a PR?

Out of curiosity, I did a bit of digging on my own, and found this interesting article about buffering, stating:

GNU libc (glibc) uses the following rules for buffering:

Stream	Type	Behavior
stdin	input	line-buffered
stdout (TTY)	output	line-buffered
stdout (not a TTY)	output	fully-buffered
stderr	output	unbuffered

So stderr is unbuffered by default, but stdout (which INFO, DEBUG and TRACE use) is only line-buffered if it's a TTY - and indeed, it works fine when running a container image using tini as PID 1 with docker run --tty ..., but that's not the common case. In the common case, when stdout is not a TTY, it is fully buffered.

Also, reading the glibc buffering docs, it looks like setlinebuf() is deprecated, and setvbuf() should be used instead, something like:

setvbuf(stdout, NULL, _IOLBF, BUFSIZ);

[orhun]

Hello, maybe slightly unrelated but I wrote a blog post about different buffering approaches, in case you might find it interesting: https://blog.orhun.dev/stdout-vs-stderr/