Journal sort order confusion

[jtmoon79]

Journal entries have two possible datetime sources; _SOURCE_REALTIME_TIMESTAMP optional field and __REALTIME_TIMESTAMP mandatory field. journalctl prefers to print _SOURCE_REALTIME_TIMESTAMP.

Problem

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 ([email protected]) (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.

Solution

Currently, s4 uses the enumerated order, and always uses __REALTIME_TIMESTAMP to determine the datetime of the entry.

However, there is an overridden implementation in JournalReader to do a few different things:

1. prefer _SOURCE_REALTIME_TIMESTAMP for printing
2. prefer _SOURCE_REALTIME_TIMESTAMP for determining the actual datetime
3. sort the entries

s4 should offer the user different printing and sorting options.
First, it should offer emulating journalctl behavior.
Later, it can be considered what other permutations should be offered.

Overall, this is a less important Issue as the current implementation is "most correct" even though it differs from official systemd behavior.

[jtmoon79]

This has been "fixed" with an override DT_USES_SOURCE_OVERRIDE in f319861
See the docs JournalReader.