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
_______________________________________________
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel
