Struct s4lib::readers::journalreader::JournalReader

pub struct JournalReader { /* private fields */ }

A wrapper for parsing a systemd .journal file using libsystemd API.

The JournalReader also writes the data to byte buffer which is later passed to a printer. So this “Reader” does some amount of “writing”. This writing is done in the next* functions.

Sorting Entries

JournalReader does “pigeon-hole” sorting of Journal Entries. The developer found some .journal files had entries not in chronological order (according to journalctl output). These out-of-order entries were very often within tens log messages of each other, and within tens of milliseconds of each other. It appeared that a matter of an overloaded systemd service will write incoming journal log entries in the happenstance order of multi-threaded processing. The result is a clustering of out-of-order entries within a small realtime window.

So this JournalReader buffers a fixed amount of processed entries (ENTRY_BUFFER_SZ), storing them in a BTreeMap sorted by DateTimeL and order encountered. The first call to next_fill_buffer will fill the JournalReader buffer and then one entry from that buffer (the earlier entry). Subsequent calls to next_fill_buffer will read another journal entry, store it in the sorted buffer, and then pop the earliest journal entry from the buffer and return that.

Overridden with DT_USES_SOURCE_OVERRIDE.

Datetime source

The sorting of entries is based on the entry datetime. This can be taken from either field __REALTIME_TIMESTAMP or field _SOURCE_REALTIME_TIMESTAMP. The JournalReader can follow the behavior of journalctl by preferring the _SOURCE_REALTIME_TIMESTAMP field if it exists. The __REALTIME_TIMESTAMP field always exists and is a reliable fallback. The value is retrieved via the sd_journal_get_realtime_usec API function in libsystemd.

The value retrieved is microseconds since the Unix Epoch. It is converted to a DateTimeL by JournalReader or the JournalEntry.

However…

Override

It was found that the _SOURCE_REALTIME_TIMESTAMP field is not always available, differs from the __REALTIME_TIMESTAMP field, and is not always in chronological order. This can lead to unexpected printing of journal entries that do not appear in chronological order.

Reviewing the journal file ./logs/programs/journal/RHE_91_system.journal revealed that the __REALTIME_TIMESTAMP field was always in chronological order and (most importantly) appears to be a more accurate chronology of events.

For example, using ./tools/journal_print.py, the following output was observed:

$ ./tools/journal_print.py ./logs/programs/journal/RHE_91_system.journal | column -t -s '|'
index  __MONOTONIC_TIMESTAMP  _SOURCE_REALTIME_TIMESTAMP  __REALTIME_TIMESTAMP        MESSAGE_ID                        MESSAGE
1      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    Linux version 5.14.0-162.6.1.el9_1.x86_64 (mockbuild@x86-vm-07.build.eng.bos.redhat.com) (gcc (GCC) 11.3.1 20220421 (Red Hat 11.3.1-2), GNU ld version 2.35.2-24.el9) #1 SMP PREEMPT_DYNAMIC Fri Sep 30 07:36:03 EDT 2022
2      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    The list of certified hardware and cloud instances for Red Hat Enterprise Linux 9 can be viewed at the Red Hat Ecosystem Catalog, https://catalog.redhat.com.
3      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    Command line: BOOT_IMAGE=(hd0,msdos1)/vmlinuz-5.14.0-162.6.1.el9_1.x86_64 root=/dev/mapper/rhel-root ro crashkernel=1G-4G:192M,4G-64G:256M,64G-:512M resume=/dev/mapper/rhel-swap rd.lvm.lv=rhel/root rd.lvm.lv=rhel/swap rhgb quiet
4      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    [Firmware Bug]: TSC doesn't count with P0 frequency!
5      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    x86/fpu: x87 FPU will use FXSAVE
6      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    signal: max sigframe size: 1440
7      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    BIOS-provided physical RAM map:
8      0:00:04.554769                                     2023-04-10 13:56:30.138000                                    BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
…
428    0:00:04.554769                                     2023-04-10 13:56:30.138000                                    Finished Create List of Static Device Nodes.
429    0:00:04.554769                                     2023-04-10 13:56:30.138000                                    Finished Create System Users.
430    0:00:04.554769                                     2023-04-10 13:56:30.138000                                    Starting Create Static Device Nodes in /dev...
431    0:00:04.554769                                     2023-04-10 13:56:30.138000  f77379a8490b408bbe5f6940505a777b  Journal started
432    0:00:04.554769                                     2023-04-10 13:56:30.138000  ec387f577b844b8fa948f33cad9a75e6  Runtime Journal (/run/log/journal/b52998310a374c8b9c676f49cc62d044) is 4.4M, max 35.4M, 30.9M free.
433    0:00:04.554769         2023-04-10 13:56:30.131199  2023-04-10 13:56:30.138000                                    Suggested group ID 65534 for nobody already used.
434    0:00:04.554769         2023-04-10 13:56:30.131762  2023-04-10 13:56:30.138000                                    Creating group 'nobody' with GID 997.
435    0:00:04.554769         2023-04-10 13:56:30.132320  2023-04-10 13:56:30.138000                                    Creating group 'users' with GID 100.
436    0:00:04.554769         2023-04-10 13:56:30.132606  2023-04-10 13:56:30.138000                                    Creating group 'dbus' with GID 81.
437    0:00:04.554769         2023-04-10 13:56:30.135833  2023-04-10 13:56:30.138000                                    Creating user 'dbus' (System Message Bus) with UID 81 and GID 81.
438    0:00:04.560769         2023-04-10 13:56:30.144435  2023-04-10 13:56:30.144000  39f53479d3a045ac8e11786248231fbf  Finished Create Static Device Nodes in /dev.
…

The index value is the enumerated order of the entries as they are returned by libsystemd API call sd_journal_next.

Entry 433 has a _SOURCE_REALTIME_TIMESTAMP that is earlier than the __REALTIME_TIMESTAMP of all prior entries. But by reading through the entry MESSAGE fields, it’s obvious that it wouldn’t make sense to have entry 433 printed as the first entry emitted from this journal file. Entry 1 is clearly the standard Linux boot start first message, and the following entries are the typical boot startup messages. So the _SOURCE_REALTIME_TIMESTAMP of 433 is inaccurate. The __REALTIME_TIMESTAMP combined with the index is the best ordering of these messages. The same is true for some other entries shown.

Confusingly, the journalctl program will prefer to print the _SOURCE_REALTIME_TIMESTAMP but will still use the enumerated order, the same order printed above. The user will see entry 433 as backwards in time, which is very confusing.

So this program just uses the enumerated order, and always uses __REALTIME_TIMESTAMP to determine the datetime of the entry.

Though JournalReader can perform different sorting behavior, that is currently overridden by hardcoded DT_USES_SOURCE_OVERRIDE.

See Issue #101.

Comparison to journalctl

The user can compare to sorted journalctl output against s4 output using commands:

$ PAGER= journalctl --output=short-iso-precise --file=./file.journal > journalctl.txt
$ s4 --journal-output=short-iso-precise --color=never ./file.journal > s4.txt
$ diff -W $COLUMNS --side-by-side --suppress-common-lines journalctl.txt s4.txt

Implementations

impl<'a> JournalReader

Implement the JournalReader.

pub const ENTRY_BUFFER_SZ: usize = 511usize

This many JournalEntry will be held in memory before any are sent to the main printing thread (unless there are fewer available).

pub fn new( path: FPath, journal_output: JournalOutput, fixed_offset: FixedOffset, file_type: FileType ) -> Result<JournalReader>

Create a new JournalReader.

NOTE: should not attempt any file reads here, similar to other *Readers::new() unless the file is compressed or archived.

pub fn mtime(&self) -> SystemTime

pub fn analyze(&mut self, ts_filter_after: &EpochMicrosecondsOpt) -> Result<()>

Set the file cursor to the first record after the given ts_filter_after or the first record if None.

This must be called once before calling next.

pub fn next(&mut self, rts_filter_before: &EpochMicrosecondsOpt) -> ResultNext

User-friendly function wrapper. Checks DT_USES_SOURCE_OVERRIDE and dispatches appropriately.

pub fn count_events_processed(&self) -> Count

Count of JournalEntrys processed (or attempted to) by this JournalReader instance.

pub fn count_events_accepted(&self) -> Count

Count of JournalEntrys processed and accepted.

pub const fn path(&self) -> &FPath

pub const fn filetype(&self) -> FileType

pub const fn filesz(&self) -> FileSz

File size in bytes

pub fn dt_first_accepted(&self) -> DateTimeLOpt

Return the DateTimeLOpt of the first Journal entry accepted by the datetime filters.

pub fn dt_last_accepted(&self) -> DateTimeLOpt

Return the DateTimeLOpt of the last Journal entry accepted by the datetime filters.

pub fn dt_first_processed(&self) -> DateTimeLOpt

Return the DateTimeLOpt of the first Journal Entry processed.

pub fn dt_last_processed(&self) -> DateTimeLOpt

Return the DateTimeLOpt of the last Journal Entry processed.

pub fn summary(&self) -> SummaryJournalReader

Return an up-to-date SummaryJournalReader instance for this JournalReader.

pub fn summary_complete(&self) -> Summary

Return an up-to-date Summary instance for this JournalReader.

Trait Implementations

impl<'a> Debug for JournalReader

fn fmt(&self, f: &mut Formatter<'_>) -> Result

Formats the value using the given formatter.