agama/rust/share/agama-journal
Ladislav Slezák 3f126ff037
Improve journal logging (#3309)
## Problem

- When saving the Agama logs we save the system log by calling the
`journactl` command and saving the output to a file.
- However, the default output format misses some important data which
might be neede for debugging, like source code locations.

## Solution

- Export the whole system journal in JSON format to save complete data
(even the values not displayed by default)
- Implement our own `journalctl` filter which prints the journal in text
format but with the additional data we need (source code locations). A
simple text log is important for easy debugging.
- The log file saved by `agama logs store` will contain 3 parts:
  - The complete log in JSON format
  - The text log with additional data (source location)
- Additional libzypp log in the y2log format (preferred by the libzypp
team), the Agama messages from `zypp-agama-sys` crate are included in
the text log as well, this is just to make the libzypp debugging easier
- Additional data can be always extracted from the complete JSON log if
needed later

## Notes

The `journalctl` command can export the journal data in a binary format
which includes all data. But processing that binary dump is not trivial.
You need to install the `systemd-journal-remote` package (not installed
by default, fortunately present in SLES16) and convert the binary dump
to the native binary journal format which then can be processed by the
`journalctl` command and finally read it as text.

That's quite complicated, simple JSON format is much easier to process
(using `jq` even from shell). Moreover I'm a bit worried about the
binary format compatibility, we need to be able to easily read and
process the logs even after 10+ years in the future...

## Additional enhancements

- Save separate libzypp log in the old y2log format, that should make
debugging easier for the libzypp team as they will get the data in the
format which they are familiar with. See more details below.
- Redirect the output of the logging commands to files, avoid storing
huge log files in memory. The whole system journal in JSON format can be
huge (>=50MB), reading all data first into memory might be problematic
on systems with low memory. So redirect the outputs to files and then
delete empty files if nothing was printed.

## Technical details

This PR adds two shell scripts which process the systemd journal and
print it in text format with more details or in a different format.

### `agama-journal` script

This script implements a custom `journalctl` output formatter. The
output format is similar to the default `journalctl` output, but there
some small (but important) changes:

#### Additional values
- Includes the error level for each message. *The displayed error level
is the systemd/syslog level, which is different than the old
y2log/libzypp error levels! Syslog uses 7 for debug, [the lower number
the higher
severity](https://en.wikipedia.org/wiki/Syslog#Severity_level)! Level 0
is emergency error.*
- Source code location (source file name, line number, name of the
function), this is supported only by few services/libararies.

#### Removed values
- Host name: I guess it is pointless to repeat the host name on each
line of the output, especially when we use the generic name "agama" for
all installations. (Though that can be changed by the `hostname=` boot
parameter.)

I was thinking about using subsecond precision for the time stamps in
the output, the journal stores them with microsecond precision. But I
think that in reality we need that precision very rarely and if needed
the precise time can be always extracted from the saved JSON format, see
below.

Of course, the output format can be changed if needed, let's take it as
the starting point...

### `agama-zypp-journal` script

This script is similar to the `agama-journal` script, but it only
exports the libzypp messages and saves them in the old YaST y2log
format.

It uses custom fields from the journal to print the original libzypp
values. For example libzypp uses different error levels than
syslog/systemd. Syslog uses level 7 as the lowest debug level, the
higher level the lower number, 0 is emergency error. While libzypp/y2log
uses 0 for debug and 5 for critical errors, with possibility to use
level 999 for temporary debugging. 😃

So when logging a message to journal we have to remap the libzypp error
level to journal value. Thanks to using the custom values in the journal
we can easily restore the original libzypp levels in this script.

## Usage

Both scripts are called when saving the logs and their output is
included in the saved tarball log.

```console
agama:~ # agama-journal | tail
Mar 24 09:51:39 <6> avahi-daemon[1946]: Registering new address record for fd00::40e8:5a9b:9461:9b7b on enp0s3.*.
Mar 24 09:51:39 <5> agama-web-server[4376]: agama-server/src/web/service.rs:130: request 274877906969: GET /api/v2/system
Mar 24 09:51:39 <4> agama-web-server[4376]: agama-network/src/nm/client.rs:222: Skipped connection because of flags: 15
Mar 24 09:51:39 <5> agama-web-server[4376]: agama-server/src/web/service.rs:139: response for 274877906969: 200 OK 23.252194ms
Mar 24 09:51:39 <6> agama-web-server[4376]: /home/lslezak/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tower-http-0.6.8/src/trace/on_eos.rs:105: end of stream
Mar 24 10:12:18 <6> NetworkManager[1898]: ../src/core/dhcp/nm-dhcp-client.c:858: <info>  [1774343538.5657] dhcp4 (enp0s3): state changed new lease, address=192.168.1.113
Mar 24 10:12:18 <6> systemd[1]: src/core/job.c(job_emit_start_message):622: Starting Network Manager Script Dispatcher Service...
Mar 24 10:12:18 <6> systemd[1]: src/core/job.c(job_emit_done_message):815: Started Network Manager Script Dispatcher Service.
Mar 24 10:12:18 <6> nm-dispatcher[5363]: sed: can't read /etc/fstab: No such file or directory
Mar 24 10:12:28 <6> systemd[1]: src/core/unit.c(unit_log_success):6168: NetworkManager-dispatcher.service: Deactivated successfully.
```

```console
agama:~ # agama-zypp-journal | head
2026-03-24 09:17:08 <1> agama(4376) [zypp-agama-sys] lib.cxx(init_target):229 Initializing target: /run/agama/zypp
2026-03-24 09:17:08 <1> agama(4376) [zypp-agama-sys] lib.cxx(zypp_ptr):144 Initializing libzypp
2026-03-24 09:17:08 <1> agama(4376) [zypp-core] PathInfo.cc(assert_dir):372 mkdir /run/agama/zypp/run 00755
2026-03-24 09:17:08 <1> agama(4376) [zypp] ZYppFactory.cc(_openLockFile):183 Open lockfile /run/agama/zypp/run/zypp.pid
2026-03-24 09:17:08 <1> agama(4376) [zypp] ZYppFactory.cc(readLockFile):238 read: Lockfile /run/agama/zypp/run/zypp.pid has pid 0 (our pid: 4376)
2026-03-24 09:17:08 <1> agama(4376) [zypp] ZYppFactory.cc(writeLockFile):250 write: Lockfile /run/agama/zypp/run/zypp.pid got pid 4376
2026-03-24 09:17:08 <1> agama(4376) [zypp] ZYppFactory.cc(_closeLockFile):201 Close lockfile /run/agama/zypp/run/zypp.pid
2026-03-24 09:17:08 <1> agama(4376) [zypp] ZYppImpl.cc(ZYppImpl):124 libzypp: 17.38.4 (01699:0:01)
2026-03-24 09:17:08 <1> agama(4376) [zypp] ZYppImpl.cc(ZYppImpl):124 libsolv: 0.7.36
2026-03-24 09:17:08 <1> agama(4376) [zypp] ZYppImpl.cc(ZYppImpl):124 TextLocale: 'en_US' (en_US)
```

But the scripts can be used also interactively when debugging a running
system. When running interactively the script colorizes the output based
on the error level:

<img width="1532" height="905" alt="image"
src="https://github.com/user-attachments/assets/2d013830-5b4f-470b-8070-0fdbeae90dc4"
/>

It is possible to show precise time stamps if needed:

```console
agama:~ # agama-journal --microseconds
Mar 24 10:16:28.883915 <6> sshd-session[5445]: Accepted publickey for root from fd00::a7b4:553c:44ce:c6b2 port 34466 ssh2: ED25519 SHA256:bUer1LwyLcDFmNMTowvyFCVDJkV7ZkPKV3/pLIO1F/U
Mar 24 10:16:28.889751 <6> systemd-logind[1875]: src/login/logind-session.c(session_start):837: New session '9' of user 'root' with class 'user' and type 'tty'.
Mar 24 10:16:28.905420 <6> systemd[1]: src/core/job.c(job_emit_done_message):815: Started Session 9 of User root.
Mar 24 10:16:28.906289 <6> sshd-session[5445]: pam_unix(sshd:session): session opened for user root(uid=0) by root(uid=0)
Mar 24 10:16:29.047948 <6> sshd-session[5450]: Received disconnect from fd00::a7b4:553c:44ce:c6b2 port 34466:11: disconnected by user
Mar 24 10:16:29.048602 <6> sshd-session[5450]: Disconnected from user root fd00::a7b4:553c:44ce:c6b2 port 34466
Mar 24 10:16:29.049754 <6> sshd-session[5445]: pam_unix(sshd:session): session closed for user root
Mar 24 10:16:29.051696 <6> systemd[1]: src/core/unit.c(unit_log_success):6168: session-9.scope: Deactivated successfully.
Mar 24 10:16:29.064042 <6> systemd-logind[1875]: src/login/logind-session.c(session_stop_scope):914: Session 9 logged out. Waiting for processes to exit.
Mar 24 10:16:29.079808 <6> systemd-logind[1875]: src/login/logind-session.c(session_finalize):968: Removed session 9.
```

Or from a previously stored JSON dump:

```sh
journalctl -o json > dump
agama-journal --microseconds --input-file dump
```

The script passes all unknown parameters to the `journalctl` call so it
is possible to do custom filtering, e.g. show all errors reported in the
last 5 minutes:

```sh
agama-journal -p err --since "5 minutes ago"
```

### Storing the logs

The new logs are included in the archive created by the `agama logs
store` command:

```console
agama:~ # agama logs store
/tmp/agama-logs-1774355656.tar.gz
agama:~ # tar tfzv /tmp/agama-logs-1774355656.tar.gz  | grep 'out.log$'
-rw-r--r-- root/root     31274 2026-03-24 13:34 agama-logs.z5Cp3M/rpm-qa.out.log
-rw-r--r-- root/root    375089 2026-03-24 13:34 agama-logs.z5Cp3M/libzypp.out.log
-rw-r--r-- root/root    611340 2026-03-24 13:34 agama-logs.z5Cp3M/journal.out.log
-rw-r--r-- root/root   4671555 2026-03-24 13:34 agama-logs.z5Cp3M/journal_json.out.log
```

## File sizes

| Name | Size | Gzip compressed |
|---|---|---|
| Original text log| 6.1MiB| 0.4MiB|
| New text log| 7.9MiB| 0.4MiB|
| JSON dump | 48MiB | 4.3MiB |
| Libzypp log | 6.9MiB | 0.3MiB |
| Complete log tarball| - | 5.4MB |

The most important part is that the whole saved tarball still fits into
the bugzilla attachment size (20MB) and there is still some room
available.


## Testing

- Tested manually
2026-03-24 16:36:47 +01:00

131 lines
4.2 KiB
Bash
Executable file

#!/bin/bash
#
# Copyright (c) [2026] SUSE LLC
#
# All Rights Reserved.
#
# This program is free software; you can redistribute it and/or modify it
# under the terms of the GNU General Public License as published by the Free
# Software Foundation; either version 2 of the License, or (at your option)
# any later version.
#
# This program is distributed in the hope that it will be useful, but WITHOUT
# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
# more details.
#
# You should have received a copy of the GNU General Public License along
# with this program; if not, contact SUSE LLC.
#
# To contact SUSE LLC about this file by physical or electronic mail, you may
# find current contact information at www.suse.com.
# Helper script which prints the messages from the systemd journal with
# additional details like code location.
# All script arguments are passed to journalctl, you can use it to filter the
# displayed messages, e.g. filter by unit with '-u sshd.service', filter by time
# with '--since "5 minutes ago"' or show only errors and higher priority with
# '-p err'..
# The timestamps are printed in the local time, to print the UTC time
# run with TZ=UTC. Hint: You can set any time zone, e.g. TZ=America/New_York.
# It accepts special "--input-file <file>" parameter to load the data from
# previously saved journal in JSON format.
# Use colors if the output goes to a terminal
if [ -t 1 ]; then
USE_COLORS="true"
else
USE_COLORS="false"
fi
SHOW_MICROSECONDS="false"
INPUT_FILE=""
JOURNAL_ARGS=()
while [ $# -gt 0 ]; do
case "$1" in
# Allow using a JSON file as input
--input-file)
INPUT_FILE="$2"
shift 2
;;
--microseconds)
SHOW_MICROSECONDS="true"
shift
;;
*)
JOURNAL_ARGS+=("$1")
shift
;;
esac
done
process_logs() {
if [ -n "$INPUT_FILE" ]; then
cat "$INPUT_FILE"
else
journalctl -o json "$@"
fi | jq --unbuffered --arg use_colors "$USE_COLORS" --arg show_microseconds "$SHOW_MICROSECONDS" -r '
# Helper function to get color based on priority
def get_color:
{
"0": "\u001b[1;91m", # Emergency - Bold Bright Red
"1": "\u001b[1;91m", # Alert - Bold Bright Red
"2": "\u001b[1;91m", # Critical - Bold Bright Red
"3": "\u001b[1;31m", # Error - Bold Red
"4": "\u001b[93m", # Warning - Bright Yellow
"5": "\u001b[1m", # Notice - Bold white
"6": "", # Informational - Default
"7": "\u001b[90m" # Debug - Grey
}[tostring] // "";
# Helper function to format timestamp
def format_timestamp:
# The journal time is in microseconds
(tonumber / 1000000 | strflocaltime("%b %e %H:%M:%S"))
+ (if $show_microseconds == "true" then "." + (tostring | .[-6:]) else "" end);
# Helper function to build the source code location string
def format_location:
[
(.CODE_FILE | select(. != null and . != "") | tostring),
(.CODE_FUNC | select(. != null and . != "") | "(" + tostring + ")"),
(.CODE_LINE | select(. != null and . != "") | ":" + tostring + ":")
]
| join("")
| select(. != "");
# Helper function to combine syslog identifier and PID
def format_syslog_pid:
[
(.SYSLOG_IDENTIFIER | select(. != null and . != "")),
(._PID | select(. != null and . != "") | "[" + tostring + "]:")
]
| join("")
| select(. != "");
# Join the requested fields into a single line
(.PRIORITY | get_color) as $color |
[
(.__REALTIME_TIMESTAMP | select(. != null and . != "") | format_timestamp),
(.PRIORITY | select(. != null and . != "") | "<" + tostring + ">"),
format_syslog_pid,
format_location,
(.ZYPP_GROUP | select(. != null and . != "") | "[" + tostring + "]"),
(.MESSAGE | select(. != null and . != "") | tostring | if $use_colors == "true" and $color != "" then $color + . + "\u001b[0m" else . end)
]
# Remove any missing/empty values and join them with a space
| map(select(. != null and . != ""))
| join(" ")
'
}
if [ "$USE_COLORS" = "true" ] && [ -n "$PAGER" ]; then
process_logs "${JOURNAL_ARGS[@]}" | $PAGER
else
process_logs "${JOURNAL_ARGS[@]}"
fi