systemd-logging

systemd-logging copied to clipboard

sd_journal_send api will return 0 (success) if no journald process is running. This will make the logs disappear silently without warning. I think it is a good idea to detect this and inform the user so that some backup strategy is used.

From std_journal_send man page:

If systemd-journald(8) is not running (the socket is not present), those functions do nothing, and also return 0.

One strategy is to use the JOURNAL_STREAM environment variable.

This environment variable is primarily useful to allow services to optionally upgrade their used log protocol to the native journal protocol (using sd_journal_print(3) and other functions) if their standard output or standard error output is connected to the journal anyway, thus enabling delivery of structured metadata along with logged messages.

Thank you.

We'll probably need some probing in init_systemd_logging(), and maybe an optional automatic fallback to a default handler.

Did some quick test and below seems to be working as expected.

import os

def is_output_connected_to_journal(fd):
    try:
        js_env = os.environ['JOURNAL_STREAM']
    except KeyError:
        return False
    stat = os.fstat(fd)
    return f"{stat.st_dev}:{stat.st_ino}" == js_env

print(is_output_connected_to_journal(1))

Let's try a simplier detection with INVOCATION_ID in #2

0.3.0 released. You can now give it a try.

Thanks! But this may not be reliable way to detect. The linked doc explains the reason:

This permits invoked processes to safely detect whether their standard output or standard error output are connected to the journal. The device and inode numbers of the file descriptors should be compared with the values set in the environment variable to determine whether the process output is still connected to the journal. Note that it is generally not sufficient to only check whether $JOURNAL_STREAM is set at all as services might invoke external processes replacing their standard output or standard error output, without unsetting the environment variable.

However it is still useful as this simpler detection will handle most of the cases.

The quote is about $JOURNAL_STREAM (on the exact stream detection), not $INVOCATION_ID. Given that, do you expect cases when $INVOCATION_ID is set and we're under systemd but journal daemon is not running (except cases when one sets that var for non systemd)?

Finally got back to investigate further. The issue is if we are not checking the JOURNAL_STREAM, we can't be sure if the stdout/stderr should really go to the journal. Consider the example below:

% ./wrap.py
Found some errors in the script!

This is the default output. It should behave the same when running under systemd.

% systemd-run --user ./wrap.py
Running as unit: run-rdb3ed0d226664f3fa568e584f44544c0.service
% journalctl --user -u run-rdb3ed0d226664f3fa568e584f44544c0.service
-- Logs begin at Sun 2019-12-15 08:51:50 EST, end at Thu 2020-03-26 17:15:07 EDT. --
Mar 26 17:15:07 hostname systemd[698]: Started /home/balki/code/systemd_logging_test/./wrap.py.
Mar 26 17:15:07 hostname python[69172]: Something went wrong!
Mar 26 17:15:07 hostname wrap.py[69171]: No Errors all good!
Mar 26 17:15:07 hostname systemd[698]: run-rdb3ed0d226664f3fa568e584f44544c0.service: Succeeded.
%

From above you can see wrap.py prints 'No Errors all good!' which is incorrect. Even though the actual error message is printed in the journal, it changes the behavior of the runner script and thus could lead to unexpected confusion. This issue won't occur if JOURNAL_STREAM is checked properly.

Source of the files here: https://gist.github.com/balki/5cad9c849a717aa3cdc21d5ee261f49f

However this change is better than before as the logs are no longer lost. Thanks! Feel free to close the issue if you are fine with current behavior.