artemist/blog
1
0
Fork 1
Code Issues Pull requests Packages Projects Releases Wiki Activity

Add more information about fields to journald post

Browse source
This commit is contained in:
Artemis Tosini 2021-06-02 02:10:28 +00:00
parent f47d43e978
commit 6d3f37f0a5
Signed by: artemist
GPG key ID: ADFFE553DCBB831E
1 changed files with 63 additions and 10 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

73
_drafts/journald-1.md
View file

@ -1,15 +1,15 @@
--- ---
layout: post layout: post
title: Jumping into journald title: Jumping into journald
date: 2021-05-31 date: 2021-06-02
--- ---
On many Linux systems, systemd-journald runs as a daemon at boot and collects your logs. You can access On many Linux systems, systemd-journald runs as a daemon at boot and collects your logs. You can access
them through journalctl but it turns out journald is a lot more complicated then just sending something to a text file. them through journalctl but it turns out journald is a lot more complicated then just sending something to a text file.
While you'll mostly see entries as a terse error message on one line, journald stores a lot more information. ## Anatomy of an Entry
For example, here's an error from my audio server, [pipewire](https://pipewire.org/). Note that some fields are reordered to make it While you'll mostly see entries as a terse error message on one line, every time you send a message journald collects and stores a lot more information.
easier to explain For example, here's an error from my audio server, [pipewire](https://pipewire.org/). Note that some fields are reordered from the raw journalctl output
```shell ```shell
artemis@starlight ~> journalctl --user -xeu pipewire.service -o export artemis@starlight ~> journalctl --user -xeu pipewire.service -o export
... ...
@ -49,13 +49,66 @@ MESSAGE=(PipeWire ALSA [.electron-wrapped]-110) client too slow! rate:256/48000
An entry consists of freeform variables with binary (though generally ASCII/US english) values. Values starting with an underscore An entry consists of freeform variables with binary (though generally ASCII/US english) values. Values starting with an underscore
are "trusted" and generated by journald while others are sent by the process along with the primary message. This helps provide are "trusted" and generated by journald while others are sent by the process along with the primary message. This helps provide
context about what exact process failed and what state it was in during that failure. Unfortunately, the [official descriptions](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html) of what these fields mean can be a bit obtuse. context about what exact process failed and what state it was in during that failure. Unfortunately the [official descriptions](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html) of what these fields mean can be a bit obtuse.
While working on my prototype for a system-journald replacement, [rjournald](https://github.com/artemist/rjournald) I've discovered what many of these mean through context or reading the systemd code: While working on my prototype for a system-journald replacement, [rjournald](https://github.com/artemist/rjournald) I've discovered what many of these mean through context or reading the systemd code. You can categorize these into one of a few types
- **_BOOT_ID** is a UUID that changes every time you start your system. This is generated by the Linux kernel and is accessable at `/proc/sys/kernel/random/boot_id`. I've found it useful to help figure out if I've rebooted my system since an error occured ### System context
These fields help you figure out if the error is coming from this computer, OS install, or boot.
- **_BOOT_ID** is a unique ID (UUID in this case) genrated at every startup. The kernel creates it and you can access the current one at `/proc/sys/kernel/random/boot_id`. I've found it useful to help figure out if I've rebooted my system since an error occured.
- **_MACHINE_ID** is a unique ID to the system which you can find in `/etc/machine-id`. This should be set on the first boot of your system by systemd and helps you figure out if the logs could be from before a system was reinstalled.
- **_HOSTNAME** is the name of the system. You probably set this in install. There's a few places to get this but journald uses `/proc/sys/kernel/hostname` (what the kernel thinks your hostname is). You can also get the hostname from systemd-hostnamed (which lets you set non-ascii hostnames for some programs) or `/etc/hostname` (which is where systemd will read your hostname and tell it to the kernel), but these might be different.
### Process permissions
These help you understand what kind of access a process has. You might get errors if a process has insufficient permission or runs as the wrong user
- **_UID** tells you what user executed the process. You can get this for your user with the command `id`. - **_UID** tells you what user executed the process. You can get this for your user with the command `id`.
- **_GID** tells you which group the process was using. While a user can have several groups, a process executes under one primary group ID - **_GID** tells you which group the process was using. While a user can have several groups, a process executes under one primary group ID
- **_CAP_EFFECTIVE** provides what [capabilities](https://linux.die.net/man/7/capabilities) a process can use. Capabilities give fine-grained privelaged access to processes without requiring them to be the root user. For example, binding to port 80 or 443 requires the CAP_NET_BIND_SERVICE capability. If _CAP_EFFECTIVE=0 then you know you've missed that capability. - **_CAP_EFFECTIVE** provides what [capabilities](https://linux.die.net/man/7/capabilities) a process can use. Capabilities give fine-grained privelaged access to processes without requiring them to be the root user. For example, binding to port 80 or 443 requires the CAP_NET_BIND_SERVICE capability. If _CAP_EFFECTIVE=0 then you know you've missed that capability.
- **_MACHINE_ID** is a unique ID to the system which you can find in `/etc/machine-id`. This should be set on the first boot of your system by systemd and helps you figure out if the logs could be from before a system was reinstalled
- **_HOSTNAME** is the name of the system. You probably set this in install. I'm not quire sure where systemd gets this, as there's multiple different places to set the hostname, including systemd-hostnamed (which lets you set non-ascii hostnames for some programs), `/etc/hostname` (which is where systemd will read your hostname and tell it to the kernel), and `/proc/sys/kernel/hostname` (what the kernel thinks your hostname is). ### systemd context
- **_TRANSPORT** How the log got to journald. As of writing I could find 6 transports: journal (using the native journald protocol), stdout (a process's standard output or error redirected to systemd), syslog (the legacy linux logging system), kernel (kernel messages you can get through the `dmesg` command), audit (logs the kernel generates about programs' activities), and driver (error messages from within journald). I'll discuss a few in more depth later If you're using journald you're almost certainly using systemd to start all your processes. Systemd organizes processes into "units", such as OS services and user sessions, and "slices", a set of similar units.
System units are started and organized by PID 1, the first program executed by the Linux kernel when you startup, while user units are organized by another instance of systemd running as your user, started by PID 1 when you login.
These are represented to the rest of the OS as a hierarchical set of "cgroups" which allow systemd to set maximum resources for units and slices (e.g. make it so users can only use 1GB of RAM at a time).
- **_SYSTEMD_CGROUP** is the full cgroup path of the process. As it's hierarchical setting a limit for e.g. `user.slice` would make it so all users together cannot go above the limit. While this is the only option you really need (systemd-journald parses the slices and units from the path it retrieves from `/proc/[pid]/cgroup`) others are included for convenience .
- **_SYSTEMD_SLICE** is the deepest slice that the PID 1 systemd assigns to the process. In this example journald chooses to say `user-1000.slice` even though the process is also in `user.slice`. Note that there is a special case for systemd: its full cgroup path is `/init.scope` but journald claims it's in the special slice `-.slice`.
- **_SYSTEMD_UNIT** is the unit that PID 1 systemd assigns to this process. For a system service this would probably be something like `dbus.service`.
- **_SYSTEMD_USER_SLICE** and **_SYSTEMD_USER_UNIT** are similar to the same fields without USER, but assigned by the user systemd
### Process context
### Time
Time, as it turns out, is extremely complicated. You'll get 3 separate time fields. Two of them are the "wall clock" time in unix time (nominally microseconds since midnight at the beginning of 1 January 1970 UTC, though leap seconds make this a bit more complicated). Unfortunately, wall clock time can jump forwards or backwards if your computer's clock is too slow or fast, respectively. Therefore, systemd also includes the "monotonic time", a number of seconds since some point in the past. This is gauranteed to always move forward so this is what you'll want to discern ordering.
Unfortunately wall clock time is also more complicated than you might expect. Linux has 4 separate monotonic timers:
- **CLOCK_MONOTONIC_RAW** counts the amount of time that Linux has spent not asleep since last boot.
- **CLOCK_MONOTONIC** is similar but will also include incremental adjustments from your time synchronization daemon noticing a fast or slow clock and reporting it to the kernel with [adjtime](https://linux.die.net/man/3/adjtime). The adjustments happen over a long period by speeding up or slowing the clock.
- **CLOCK_BOOTTIME** is similar to CLOCK_MONOTONIC but also counts time where they system is asleep.
- **CLOCK_MONOTONIC_COARSE** is similar to CLOCK_MONOTONIC but requires slightly less work in the Kernel and is less accurate.
Now for the actual fields:
- **_SOURCE_REALTIME_TIMESTAMP** is the UTC timestamp collected as soon as journald receives the message
- **__REALTIME_TIMESTAMP** is the UTC timestamp collected when message is written into the journal file. It takes a bit of time for journald to read all the context data out of /proc so this is a bit later.
- **__MONOTONIC_TIMESTAMP** is the monotonic timestamp from when the message is written into the journal file. Journald uses CLOCK_MONOTONIC but there's not much of a specification to tell people implementing it which one to use.
### Reader context
Fields starting with two underscores are generated by `journalctl` while reading.
### The actual message
Finally there's the untrusted message sent by the process.
- **MESSAGE** is the only required field and is what shows up in `journalctl` when you don't use `-o export`.
- Some programs also send where the error comes from with **CODE_FILE**, **CODE_LINE**, and **CODE_FUNC**
- **PRIORITY** is how severe the issue is with 0 being the most importand and 7 being the least. In this example, 4 means "warning"
- **SYSLOG_IDENTIFIER** is the program identifier and is what you would get as the program source if you were using syslogd (as you would before systemd)
## Transports
There's still one field I haven't described: **_TRANSPORT**. This requires a little more context.
Journald can get messages from one of 6 separate sources: **journal** (using the native journald protocol), **stdout** (a process's standard output or error redirected to systemd), **syslog** (the legacy linux logging system), **kernel** (kernel messages you can get through the `dmesg` command), **audit** (logs the kernel generates about programs' activities), and **driver** (error messages from within journald). Each has their own peculariaties from both the journald side and the client side but I'll mostly be talking about journald, stdout, and syslog.
### Native (journal)
### Service output (stdout)
### Legacy (syslog)
## Overview
Anything related to Linux quickly turns into a huge rabbit hole. I could certainly write articles on many of the
This is mostly from my own experimentation. If you have more inforomation and noticed an error, please contact me. I'd be happy to correct anything.