logging: use journald logging for all systemd services

[orndorffgrant]

Why is this needed?

This PR brings journald logging to all systemd services, plus a few small related refactors.

Test Steps

./tools/test-in-lxd.sh xenial
apt update
# ensure logs of esm_cache end up in journald

Checklist

• I have updated or added any unit tests accordingly
• I have updated or added any integration tests accordingly
• [n/a] Changes here need to be documented, and this was done in:

Does this PR require extra reviews?

• Yes
• No

[github-actions]

Jira: This PR is not related to a Jira item. (The PR title does not include a SC-#### reference)

GitHub Issues: No GitHub issues are fixed by this PR. (No commits have Fixes: #### references)

Launchpad Bugs: No Launchpad bugs are fixed by this PR. (No commits have LP: #### references)

Documentation: The changes in this PR do not require documentation changes.

👍 this comment to confirm that this is correct.

[aciba90]

LGTM, thanks for the refactors.

[lucasmoura]

@orndorffgrant should we use our JSON format when logging to journalctl ? I am just wondering if we need to be consistent with the other logs there. But maybe this is not needed

[orndorffgrant]

@lucasmoura I think it should use the json logging to be consistent. The setup_journald_logging function does use the JsonArrayFormatter and I just updated the integration test to actually check the json output. Does that align with what you were thinking?

[lucasmoura]

My rationale is that it shouldn't to be honest, just to align with the other journalctl entries. But I don't think is an actual problem if we keep the JSON output

[orndorffgrant]

I'd rather keep consistency with our own logs than with journald's default formatting. journald's logging itself is structured and can be formatted as json as well, though in that case our json message becomes an escaped json string value in their json and looks like this:

...
"_CMDLINE":"/usr/bin/python3 /usr/lib/ubuntu-advantage/esm_cache.py",
"__CURSOR":"s=e4ea46b1825d4b5d833f9f8a48dccd3c;i=862;b=28db989000224dc39694c489bad64176;m=40a4ff859d;t=608138598a742;x=35915d735a50dc59",
"MESSAGE":"[\"2023-10-19T15:36:39.038\", \"WARNING\", \"ubuntupro.apt\", \"fail\", 871, \"Failed to fetch ESM Apt Cache item: https://esm.ubuntu.com/apps/ubuntu/dists/jammy-apps-security/InRelease\", {}]",
"SYSLOG_IDENTIFIER":"python3"
...

So by formatting our message string in json, we're just adding a nested structure within the journald structure. I don't know if this is widely used practice, but I don't think I'd consider it a bad practice (unless I'm unaware of some downside).

A couple things about using our json formatter:

• we can use journald format cat and get only our jsonlines
• it looks the same as our other logs (and can be processed programmatically in the future the same way if desired)
• it includes all the nice context that our json formatter includes, including the optional "extras" in the last position, which we don't use much now, but I would like to use more.

We can talk more about this post-standup tomorrow or next week too

[orndorffgrant]

@sergiodj @athos-ribeiro @lucasmoura After our discussion in Riga, I've updated this to remove the json formatting in journald logs.

We still want to include multiple fields with structure, though, so I've introduced a simpler (but more fragile) |-delimited format.

Taking the example from my last comment here, it would now look like this:

...
"_CMDLINE":"/usr/bin/python3 /usr/lib/ubuntu-advantage/esm_cache.py",
"__CURSOR":"s=e4ea46b1825d4b5d833f9f8a48dccd3c;i=862;b=28db989000224dc39694c489bad64176;m=40a4ff859d;t=608138598a742;x=35915d735a50dc59",
"MESSAGE":"WARNING|ubuntupro.apt|fail|872|Failed to fetch ESM Apt Cache item: https://esm.ubuntu.com/apps/ubuntu/dists/xenial-apps-security/InRelease|{}",
"SYSLOG_IDENTIFIER":"python3"
...

Do you think this is better or worse than the json formatting?

[orndorffgrant]

And I haven't explained yet, we don't want to pull python3-systemd into ubuntu-minimal just for structured logging support

[athos-ribeiro]

@sergiodj @athos-ribeiro @lucasmoura After our discussion in Riga, I've updated this to remove the json formatting in journald logs.

We still want to include multiple fields with structure, though, so I've introduced a simpler (but more fragile) |-delimited format.

Taking the example from my last comment here, it would now look like this:

...
"_CMDLINE":"/usr/bin/python3 /usr/lib/ubuntu-advantage/esm_cache.py",
"__CURSOR":"s=e4ea46b1825d4b5d833f9f8a48dccd3c;i=862;b=28db989000224dc39694c489bad64176;m=40a4ff859d;t=608138598a742;x=35915d735a50dc59",
"MESSAGE":"WARNING|ubuntupro.apt|fail|872|Failed to fetch ESM Apt Cache item: https://esm.ubuntu.com/apps/ubuntu/dists/xenial-apps-security/InRelease|{}",
"SYSLOG_IDENTIFIER":"python3"
...

Do you think this is better or worse than the json formatting?

Thanks, Grant!

Would you mind showing what an old (current) log entry would look like compared to the new format?
Do you think there are people out there parsing those logs somehow and would this break their workflows?

[orndorffgrant]

Thanks for looking @athos-ribeiro!

Prior to this PR, most services logged to /var/log/ubuntu-advantage.log in the JSONArray format. This was not done in a multi-process-safe way. Any messages that ended up in journald were accidental and did not contain any structure, e.g. it would just be the message string like "Failed to fetch ESM Apt Cache item: https://esm.ubuntu.com/apps/ubuntu/dists/xenial-apps-security/InRelease".

Two services already logged to journald in the JSONArray format.

So there are several changes here from the perspective of someone interested in our logs:

1. Some logs that used to appear in ubuntu-advantage.log will no longer appear
2. More logs will show up in journald for their respective services
3. logs in journald that used to be JSONArray formatted will no longer be JSONArray formatted
4. logs in journald that used to be just a string will now have some structure and extra information

We haven't considered backwards compatibility of our logs very seriously in the past. The biggest breaking change, though, would be moving away from JSONArray formatting for the services that were already using it. Anything else would've been handled as a string, so adding structure wouldn't break it significantly IMO.

[panlinux]

Thanks for looking @athos-ribeiro!

Prior to this PR, most services logged to /var/log/ubuntu-advantage.log in the JSONArray format. This was not done in a multi-process-safe way. Any messages that ended up in journald were accidental and did not contain any structure, e.g. it would just be the message string like "Failed to fetch ESM Apt Cache item: https://esm.ubuntu.com/apps/ubuntu/dists/xenial-apps-security/InRelease".

Two services already logged to journald in the JSONArray format.

So there are several changes here from the perspective of someone interested in our logs:

1. Some logs that used to appear in ubuntu-advantage.log will no longer appear
2. More logs will show up in journald for their respective services
3. logs in journald that used to be JSONArray formatted will no longer be JSONArray formatted
4. logs in journald that used to be just a string will now have some structure and extra information

We haven't considered backwards compatibility of our logs very seriously in the past. The biggest breaking change, though, would be moving away from JSONArray formatting for the services that were already using it. Anything else would've been handled as a string, so adding structure wouldn't break it significantly IMO.

This is quite the breaking change. If I, as a user, would be parsing the logs, I would be very annoyed with such a change in an LTS upgrade.
Have you considered a config option to toggle between these logging formats? On upgrade, the logging format wouldn't change, but on a fresh install, it would be what this PR is proposing?

[panlinux]

Other points:

1. You should document the logging. How it's done, in which format, where.
2. Are there more logging changes coming? When will this be done?

[orndorffgrant]

Thank you for taking a look @panlinux - we're in agreement I think. Looking back, my tone was a bit flippant in my last comment, but the intent was to show that I thought it was a bad idea to change the format from JSONArray to something else.

My original proposal was to add JSONArray formatting to previously unstructured messages in journald. I would still prefer to only do that, since it would add additional information to the logs and I don't think it should be considered a breaking change (we added the same structured logging to ubuntu-advantage.log in the past).

So then the total set of changes in this PR would be:

1. Some log messages that used to appear in ubuntu-advantage.log will no longer appear
2. More logs will show up in journald for their respective services
3. Logs in journald that used to be just a string will now have the JSONArray format with additional information (the same format as ubuntu-advantage.log)

Then pro logging will be the same format everywhere and we will document the format. With a structured extensible logging format in place everywhere that pro cares about, then we shouldn't ever need logging format changes in the future.

If you think that is acceptable, then I'd like to avoid a config option for logging formats.

[lucasmoura]

Just to double check, why is the function name fail here ?

[orndorffgrant]

Inside update_esm_caches, an EsmAcquireProgress class is defined with a fail method that is called by the apt library when an error occurs. That method is where we log this line

[orndorffgrant]

@panlinux @lucasmoura I've updated this PR so it only does the following:

• Removes not-multiprocess-safe logging to same file from multiple processes
• Each systemd service that previously did not log to journald now does
  • These services log in JSON format

There are no breaking changes.

Is this okay?

[renanrodrigo]

imho this is a good changeset after all the discussion

[orndorffgrant]

CI fail unrelated

[orndorffgrant]

I'm going ahead and merging the least controversial version of this PR (new logging to journald using JSON format).
We can revisit at SRU review time if necessary.