2

I have a trivial systemd service (called "testpath") which simply prints some output to be captured by the journal. The journal is intermittently and unpredictably losing part of the output. The behaviour seems so erratic, and the test case so trivial, that it's hard to see how it could be any kind of intended behaviour.

Can anyone offer a explanation in terms of expected systemd behaviour? Failing that, can anyone suggest a strategy to try to isolate this as a bug?

The service simply runs this script:

% cat ~/tmp/testpath.bin 
#!/bin/bash

sleep 0.1
ps -p $$
echo Echo statement.

The expected behaviour is that both the ps and echo outputs should appear in the journal at each system invocation. But instead the the ps output appears maybe half the time, and the echo output maybe 90% of the time. For example, manually running systemctl --user start testpath produced this journal:

% journalctl --user -u testpath.service --follow
<some lines elided>
Oct 30 00:47:36 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:47:36 skierfe testpath.bin[862530]:     PID TTY          TIME CMD
Oct 30 00:47:36 skierfe testpath.bin[862530]:  862527 ?        00:00:00 testpath.bin
Oct 30 00:47:36 skierfe testpath.bin[862527]: Echo statement.
Oct 30 00:53:17 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:53:17 skierfe testpath.bin[863505]: Echo statement.
Oct 30 00:53:20 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:53:21 skierfe testpath.bin[863545]: Echo statement.
Oct 30 00:53:23 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:53:23 skierfe testpath.bin[863553]: Echo statement.
Oct 30 00:53:26 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:53:26 skierfe testpath.bin[863558]: Echo statement.
Oct 30 00:53:28 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:53:33 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:53:33 skierfe testpath.bin[863577]:     PID TTY          TIME CMD
Oct 30 00:53:33 skierfe testpath.bin[863577]:  863574 ?        00:00:00 testpath.bin
Oct 30 00:53:33 skierfe testpath.bin[863574]: Echo statement.
Oct 30 00:53:37 skierfe systemd[1518]: Started Testpath service.
Oct 30 00:53:37 skierfe testpath.bin[863579]: Echo statement.

The unit file:

skierfe:(f)..config/systemd/user % cat ~/.config/systemd/user/testpath.service
[Unit]
Description = Testpath service

[Service]
ExecStart = %h/tmp/testpath.bin

Things I've considered or tried (none of which have helped):

  • System resource contention: no, new Core i5 system with low loadavg
  • Rate-limit parameters per #774809: no, RateLimitInterval and RateLimitBurst are commented out in /etc/systemd/journald.conf, and the logging rate is trivial anyway
  • Extending or removing the sleep command (timing issues?)
  • Changing the service to Type=oneshot
  • Setting explicit StandardOutput=journal per #1089887

None of these have changed the behaviour.

I'm on x86_64 Ubuntu 22.04 with current package updates.

skierfe:(f)~/tmp % systemd --version
systemd 249 (249.11-0ubuntu3.6)
+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified
Dave Hughes
  • 21

1 Answers1

0

I met similar issue. I was writing a program in C. And systemd journalctl does not log my program's printf() stdout. I searched online and from these links https://unix.stackexchange.com/questions/725331#comment1376185_725331 https://stackoverflow.com/a/7876743 https://unix.stackexchange.com/questions/785686#comment1505589_785686 I learned that I need fflush(stdout); after printf() for systemd to log my stdout. Without fflush, fprintf stderr works, printf not work, fprintf stdout not work. Maybe other ways to flush buffers or disable buffering also works.

If the program you want systemd journalctl to log is in C, one way to solve your issue is to edit the program to add fflush(stdout); after printf and fprintf.

Copied from https://serverfault.com/a/1180972/1234782

xyz
  • 21