I have a systemd service which logs to stdout. From there, systemd captures STDOUT and writes it to the journal.

I use a common idiom for handling an error where I echo some diagnostics, then exit with a non-zero error code:

echo "my final error";
exit 1;

My problem is that this final echo line makes it to the journal, but is not properly associated with my "unit". By looking at journalctl -o json-pretty, I can see what the difference is. The final logging lacks the properties _SYSTEMD_CGROUP and _SYSTEMD_UNIT.

What I think is happening is a kind of race condition. I suspect that that the bash script doesn't wait for journald to fully process the before moving on to the exit line. So the exit line is reached before journald finishes processing the log entry. journald tries to look up the unit that sent the logging, but now can't find it since the unit is no longer running.

If I'm right, I could probably work around the issue by putting sleep 1 before my exit 1 statement, but is there a better way to get the final logs property attributed?

I'm using systemd version 229 on Ubuntu 16.04.

  • 1
    What happens when the log line is sent instead to stderr? That is less likely to be block or line buffered like stdout is, and thus less likely to be lost. – thrig Jun 22 '16 at 22:23
up vote 3 down vote accepted

@mark-stosberg, this is a known issue: journald is unable to attribute messages incoming from processes that exited to their cgroup, due to /proc vs SCM_CREDS race

You can find a workaround there: https://github.com/systemd/systemd/issues/2913#issuecomment-219702148

try SyslogIdentifier=

Sets the process name to prefix log lines sent to the logging system or the kernel log buffer with.

and run journalctl _SYSTEMD_UNIT=unit + UNIT=unit + SYSLOG_IDENTIFIER=id

I researched this, and it appears to be a known issue with systemd that there is a pull request for.

The fix involves caching the metadata for the service, so that even if the service has exited, the metadata for it is still available to properly categorize the last few logs.

It's also considered an open bug in CoreOS, which uses systemd.

The bug is also tracked on the systemd freedesktop.org bug tracker under as:

Further testing found the issue of missing log attribution is more severe with user units-- I assume that's a separate issue. For system units, the race condition is relatively small and adding sleep 1; just before exit in the service script may add enough padding before the the last log printed and the exit to workaround the issue.

Your Answer

 

By clicking "Post Your Answer", you acknowledge that you have read our updated terms of service, privacy policy and cookie policy, and that your continued use of the website is subject to these policies.

Not the answer you're looking for? Browse other questions tagged or ask your own question.