[systemd-devel] journal: Receiving messages from the future

[Michael Littlejohn]

Hi,

TL;DR:
Server is receiving log message via systemd-journal-remote from 14s in the future (sender clock is 14s fast). Causes journal files to close, rotate and start anew on every message/batch. Check at journal-file.c:621 is checking for messages "from the future" from perspective of local system, rather than checking if messages are in or out of order within context of that message stream. Discuss.

---

Could find any related bugs/discussions. Apologies if this is old news.

I'm testing out systemd-journal-remote and systemd-journal-upload for shipping logs between to systems; 'host-A' and 'server-A'.

Both of these systems are VMs, and I have the remote transport working just fine. I'm catching the logs in systemd-journal-remote ("passive mode") and putting them into /var/log/journal/remote/. However I started to notice that every time a new messages were received, journald would rotate the current active journal out and start a new one.

I enabled debugging and and got the following:

Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Journal file /var/log/journal/remote//remote-192.168.252.19.journal is from the future, refusing to append new data to it that'd be older.
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: File /var/log/journal/remote//remote-192.168.252.19.journal corrupted or uncleanly shut down, renaming and replacing.
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Fixed min_use=1.0M max_use=1.1G max_size=128.0M min_size=512.0K keep_free=1.7G n_max_files=100
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Reserving 233016 entries in hash table.
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Opened output file /var/log/journal/remote//remote-192.168.252.19.journal
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Creating source for passive fd:8 (<ip of host-a>)
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Added RemoteSource as connection metadata 0x55e20d4f5830
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Queueing response 202: OK.
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Cleaning up connection metadata 0x55e20d4f5830
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Writer ref count 1
Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Closing journal file /var/log/journal/remote//remote-<ip of host-a>.journal.

This batch of messages repeats roughly every 10 seconds or so which is the rate at which I was logging messages on 'host-A'.

It turns out that the system clocks of 'host-A' and 'server-A' have drifted out of sync over time - with 'host-A' currently standing about 14 seconds ahead of the server.

I looked for the line generating the "from the future" debug message, it's from this snippet (journal-file.c:618-624):

```
                /* Don't permit appending to files from the future. Because otherwise the realtime timestamps wouldn't
                 * be strictly ordered in the entries in the file anymore, and we can't have that since it breaks
                 * bisection. */
                if (le64toh(f->header->tail_entry_realtime) > now(CLOCK_REALTIME)) {
                        log_debug("Journal file %s is from the future, refusing to append new data to it that'd be older.", f->path);
                        return -ETXTBSY;
                }

```

My thinking goes like this (assume start = now = 0):

1) A new journal is created with f->header->tail_entry_realtime = start
2) We process appending a new message whose `realtime = start+14s`
3) We perform the above check, passing it  because 0 > now is false
4) We update the journal file header with the realtime from the message: f->header->tail_entry_realtime = start+14s
5) Wait 10 seconds, now = 10
6) We received a new message with a realtime = now+14s
7) We perform the above check, except at this time we're comparing start+14s to now (14 > 10). The check return as true, we log the above output and send the return code.
8) We rotate the logs
9) Return to step 1.

---

I think the assumption in the check is that the messages being logged will always come from the local system, so you shouldn't ever have to worry about time de-synchronisation issues. However, given that systemd-journal-remote exists, that doesn't really hold true anymore.

I can only think of one practicable solutions, and that is to change the check so that it's comparing the f->header->tail_entry_realtime and the realtime of the message that's being logged.

This should mean that we will still complain about messages from the future being put into the wrong journal (causing a rotation and a new journal file to be spawned) but within the context of messages coming from the same host being put into the same journal consistently, even if the messages are from the future from the perspective of the local system, they wouldn't be "from the future"/out of order within the context of that series of logs from that host.

I'm willing to generate a patch for the issue (and will begin doing so in the background). This will be my first time contributing to systemd - help/guidance for contributions would appreciated.

Cheers,
M
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20171013/79aa4159/attachment-0001.html>