[systemd-devel] systemd-timesync and journalctl questions

[Eero Tamminen]

Hi,

On 24.08.2018 18:18, Uoti Urpala wrote:
> On Fri, 2018-08-24 at 14:52 +0300, David Weinehall wrote:
>> The second time-related issue pertains to journalctl.
>>
>> It seems that journalctl logs (or at least displays) events in date/clock order, not in
>> sequence order. While this is definitely useful when trying to correlate different logs
>> against each other, it also means that events that happen after a date adjustment might
>> end up before already existing entries, thus breaking the sequentialness of the log,
>> as follows:
>>
>> Date incorrect set to 2023:
>>
>> Log message 1
>> Log message 2
>>
>> Date corrected to be 2018:
>>
>> Log message 3
>> Log message 1
>> Log message 2
>>
>> Typically this is not how we want our log to behave. Is there any way to
>> show the log in sequential order?
> 
> Within one journal file, entries are stored in the order they are
> received, and the normal tools like journalctl will also display events
> from within the file in that order. Output like the above shouldn't be
> the typical consequence of changing time during a single boot, as the
> later entries should usually keep being written in the same file as the
> previous ones. (It can happen, but your "reproduction steps" above are
> likely incomplete as to what is actually required to see such effects).
> 
> Where you can see issues is between entries stored in separate journal
> files. Those may not contain information that would allow comparing two
> entries stored in the different files by anything other than the
> unreliable realtime timestamp.

Shouldn't globally sequential ordering be one of the first requirements
for any log system?


> Note that the journal display code has some fairly serious breakage in
> the area of handling messages that may have unreliable timestamps,
> which may cause issues such as some messages not being shown at all.
> The commit message of the proposed patch in the message linked below is
> probably the best writeup (no fixes have been applied to this area
> AFAIK):
> 
> https://lists.freedesktop.org/archives/systemd-devel/2017-December/039976.html

The log messages could have disappeared, it's hard to say with
journal containing info about dozens of reboots with the same time
stamps (this is from an embedded device without battery backed clock, 
where systemd daemon doesn't get time synced early enough from network 
that log messages would have correct time stamps).

At least the latest messages logged were not at the end of the 
journalctl output where they should have.


Regards,

	- Eero