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

2018-05-18 Thread Ivan Kurnosov 
I'm observing it on the ubuntu bionic that comes with systemd 237

On 19 May 2018 at 07:27, Lennart Poettering  wrote:

> On Fr, 18.05.18 09:02, Ivan Kurnosov (zer...@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 
> >
> > 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
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

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

2018-05-18 Thread Lennart Poettering 
On Fr, 18.05.18 09:02, Ivan Kurnosov (zer...@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 
> 
> 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
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

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

2018-05-17 Thread Ivan Kurnosov 
That's it.

Yep, I can see it in the `journalctl` but it's not in `journalctl -u
servicename`

Thanks

On 18 May 2018 at 11:44, Michael Biebl  wrote:

> 2018-05-17 23:02 GMT+02:00 Ivan Kurnosov :
>
> > Here is the example of the `journald` output for the service:
>
> I assume you used journalctl -u bla.service?
> If so, do the log messages turn up if you run journalctl?
>
> Then this might be another instance of
> https://github.com/systemd/systemd/issues/2913
>
> --
> Why is it that all of the instruments seeking intelligent life in the
> universe are pointed away from Earth?
>



-- 
With best regards, Ivan Kurnosov
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

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

2018-05-17 Thread Michael Biebl 
2018-05-17 23:02 GMT+02:00 Ivan Kurnosov :

> Here is the example of the `journald` output for the service:

I assume you used journalctl -u bla.service?
If so, do the log messages turn up if you run journalctl?

Then this might be another instance of
https://github.com/systemd/systemd/issues/2913

-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

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

2018-05-17 Thread Ivan Kurnosov 
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 

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?

-- 
With best regards, Ivan Kurnosov
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel