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

[Ivan Kurnosov]

I'm observing it on the ubuntu bionic that comes with systemd 237

On 19 May 2018 at 07:27, Lennart Poettering <lennart at poettering.net> wrote:

> 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
>



-- 
With best regards, Ivan Kurnosov
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20180519/ffc824f1/attachment.html>