[systemd-devel] How to guarantee the stdout buffer between systemd and journald is flushed when program quits?

[Lennart Poettering]

On Fr, 18.05.18 09:02, Ivan Kurnosov (zerkms at zerkms.ru) wrote:

> Hi,
> 
> I originally asked this question on the stackoverflow (
> https://stackoverflow.com/q/50400145/251311) but I feel I wouldn't get an
> answer there.
> 
> The simplified example that demonstrates a problem is
> 
>     #include <stdio.h>
> 
>     int main(void)
>     {
>         printf("foo\n");
>         fflush(stdout);
>         getchar();
>         return 0;
>     }
> 
> (it's not programming language specific though - the original application I
> discovered the problem with is in Go).
> 
> If it's compiled and is run by the following unit:
> 
>     [Unit]
>     Description=description
>     After=network.target
> 
>     [Service]
>     ExecStart=/path/to/binary
> 
>     [Install]
>     WantedBy=multi-user.target
> 
> then on `systemctl restart` `journald` would in most cases not get the
> `foo\n` output, while `syslog` successfully writes it down to the
> `/var/log/syslog`.
> 
> Here is the example of the `journald` output for the service:
> 
>     May 18 08:30:38 hostname systemd[1]: Stopped servicename
>     May 18 08:30:38 hostname systemd[1]: Started servicename
>     May 18 08:30:38 hostname systemd[1]: Stopped servicename
>     May 18 08:30:38 hostname systemd[1]: Started servicename
>     May 18 08:30:38 hostname servicename[7701]: foo
>     May 18 08:30:41 hostname systemd[1]: Stopped servicename
>     May 18 08:30:41 hostname systemd[1]: Started servicename
>     May 18 08:30:46 hostname systemd[1]: Stopped servicename
>     May 18 08:30:46 hostname systemd[1]: Started servicename
> 
> and then the corresponding part of the `/var/log/syslog`:
> 
>     May 18 08:30:38 hostname systemd[1]: Stopped servicename.
>     May 18 08:30:38 hostname systemd[1]: Started servicename.
>     May 18 08:30:38 hostname servicename[7682]: foo
>     May 18 08:30:38 hostname systemd[1]: Stopped servicename.
>     May 18 08:30:38 hostname systemd[1]: Started servicename.
>     May 18 08:30:38 hostname servicename[7701]: foo
>     May 18 08:30:41 hostname systemd[1]: Stopped servicename.
>     May 18 08:30:41 hostname systemd[1]: Started servicename.
>     May 18 08:30:41 hostname servicename[7720]: foo
>     May 18 08:30:46 hostname systemd[1]: Stopped servicename.
>     May 18 08:30:46 hostname systemd[1]: Started servicename.
>     May 18 08:30:46 hostname servicename[7739]: foo
> 
> What would be a way to **guarantee** journald received the `stdout`, if any?

It is guaranteed that it wil get the data. However, you are probably
running into this:

https://github.com/systemd/systemd/issues/2913

i.e. stuff that is logged right before a process exits might miss the
metadata we need for "-u" to work correctly. The message itself is not
lost though, you should see it if you drop the "-u"...

The situation is improved a ton with systemd 235 where metadata is
cached in journald if possible, which increases the chance we wil have
the metadata around even if the sending process is already gone. It
fixes most common cases, but there are still some cases around which
aren't covered by that.

hence, make sure to run 235 (or some release that backported the
caching).

Lennart

-- 
Lennart Poettering, Red Hat