Service output missing from journal?

[Uwe Geuder <systemd-devel-ugeuder@xxxxxxxxxxx>]

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.

Regards,

Uwe


Uwe Geuder
Neuro Event Labs Oy
Tampere, Finland
uwe.gxuder@xxxxxxxxxxxxxxxxxx (bot check: fix 1 obvious typo)