How to fix unit attribution of last lines of systemd logging before exit

systemdsystemd-journald

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.

Best Answer

@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

Related Question