Skip to content

Improve journal logging#3309

Merged
lslezak merged 14 commits intomasterfrom
better-logs
Mar 24, 2026
Merged

Improve journal logging#3309
lslezak merged 14 commits intomasterfrom
better-logs

Conversation

@lslezak
Copy link
Copy Markdown
Contributor

@lslezak lslezak commented Mar 20, 2026

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! 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.

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.
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:

image

It is possible to show precise time stamps if needed:

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:

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:

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:

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

lslezak added 2 commits March 19, 2026 22:52
- Export the whole system journal in JSON format
  (to save complate data, even the values not displayed by default)
- Save the journal log with additional data (source code locations)
- Save separate libzypp log in the old y2log format
- Redirect the output of the logging commands to files,
  avoid storing huge log files in memory.
@lslezak lslezak marked this pull request as ready for review March 24, 2026 12:41
@lslezak lslezak merged commit 3f126ff into master Mar 24, 2026
16 checks passed
@lslezak lslezak deleted the better-logs branch March 24, 2026 15:36
@imobachgs imobachgs mentioned this pull request Apr 14, 2026
imobachgs added a commit that referenced this pull request Apr 14, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants