[systemd-devel] Service output missing from journal?

[Lennart Poettering]

On Mo, 04.07.22 23:15, Michael Biebl (mbiebl at gmail.com) wrote:

> Am Mo., 4. Juli 2022 um 19:36 Uhr schrieb Lennart Poettering
> <lennart at poettering.net>:
> >
> > eOn So, 03.07.22 19:29, Uwe Geuder (systemd-devel-ugeuder at snkmail.com) wrote:
> >
> > > Hi!
> > >
> > > When I run the command given below on a current Fedora CoreOS system
> > > (systemd 250 (v250.6-1.fc36)) I get a result I absolute cannot understand.
> > > Can anybody help me with what is wrong there?
> > >
> > > $ systemd-run --user sh -c 'while true; do echo foo; df -h /var/log/journal/; echo $?; sleep 3; done'
> > > Running as unit: run-r9a155474889b4d40a1ac119823bdc2bf.service
> > > $ journalctl --user -f -u run-r9a155474889b4d40a1ac119823bdc2bf
> > > [ ... similar lines redacted ... ]
> > > Jul 03 15:25:08 ip-172-31-8-116 sh[366900]: 0
> > > Jul 03 15:25:11 ip-172-31-8-116 sh[366900]: foo
> > > Jul 03 15:25:11 ip-172-31-8-116 sh[366900]: 0
> > > Jul 03 15:25:14 ip-172-31-8-116 sh[366900]: foo
> > > Jul 03 15:25:14 ip-172-31-8-116 sh[366900]: 0
> > > Jul 03 15:25:17 ip-172-31-8-116 sh[366900]: foo
> > > Jul 03 15:25:17 ip-172-31-8-116 sh[366900]: 0
> > > Jul 03 15:25:20 ip-172-31-8-116 sh[366900]: foo
> > > Jul 03 15:25:20 ip-172-31-8-116 sh[366941]: Filesystem      Size  Used Avail Use% Mounted on
> > > Jul 03 15:25:20 ip-172-31-8-116 sh[366941]: /dev/nvme0n1p4  9.5G  8.1G  1.5G  86% /var
> > > Jul 03 15:25:20 ip-172-31-8-116 sh[366900]: 0
> > > Jul 03 15:25:23 ip-172-31-8-116 sh[366900]: foo
> > > Jul 03 15:25:23 ip-172-31-8-116 sh[366900]: 0
> > > Jul 03 15:25:26 ip-172-31-8-116 sh[366900]: foo
> > > Jul 03 15:25:26 ip-172-31-8-116 sh[366900]: 0
> > > Jul 03 15:25:29 ip-172-31-8-116 sh[366900]: foo
> > > Jul 03 15:25:29 ip-172-31-8-116 sh[366900]: 0
> > > [...]
> > >
> > > So the output from the df command appears in the journal pretty rarely,
> > > appearingly at random intervals. When I run the same loop on the
> > > command line the output occurs every time.
> > >
> > > The problem was originally noted in a somewhat loaded system. However,
> > > above reproducer (including the 2 echo commands and a shorter sleep)
> > > shows the same problem even on an idling machine.
> >
> > https://github.com/systemd/systemd/issues/2913
>
> I thought about this as well, but in this case the service is still
> running. So I'm not sure if #2913 applies here.

The service is, but the "df" process exits extremely quickly, before
we can figure out what it belongs to. See the PIDs where it works,
they are different from your shell script's PID, because they are
short-lived child processes.

Lennart

--
Lennart Poettering, Berlin