<html> <head> <meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1"> <style type="text/css" style="display:none;"> P {margin-top:0;margin-bottom:0;} </style> </head> <body dir="ltr"> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> Hi,</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> TL;DR:</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 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.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> ---</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> Could find any related bugs/discussions. Apologies if this is old news.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> I'm testing out systemd-journal-remote and systemd-journal-upload for shipping logs between to systems; 'host-A' and 'server-A'.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 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/. <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">However</span><span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"> 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.</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"><br> </span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">I enabled debugging and and got the following:</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"><br> </span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"> <div> <div>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.</div> <div>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.</div> <div>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</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Reserving 233016 entries in hash table.</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Opened output file /var/log/journal/remote//remote-192.168.252.19.journal</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Creating source for passive fd:8 (<ip of host-a>)</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Added RemoteSource as connection metadata 0x55e20d4f5830</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Queueing response 202: OK.</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Cleaning up connection metadata 0x55e20d4f5830</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Writer ref count 1</div> <div>Oct 13 11:25:03 mlj-deb9 systemd-journal-remote[21380]: Closing journal file /var/log/journal/remote//remote-<ip of host-a>.journal.</div> <div><br> </div> <div>This batch of messages repeats roughly every 10 seconds or so which is the rate at which I was logging messages on 'host-A'.</div> <div><br> </div> </div> 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.</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"><br> </span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">I looked for the line generating the "from the future" debug message, it's from this snippet (journal-file.c:618-624):</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"><br> </span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">```</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"> <div> /* Don't permit appending to files from the future. Because otherwise the realtime timestamps wouldn't</div> <div> * be strictly ordered in the entries in the file anymore, and we can't have that since it breaks</div> <div> * bisection. */</div> <div> if (le64toh(f->header->tail_entry_realtime) > now(CLOCK_REALTIME)) {</div> <div> log_debug("Journal file %s is from the future, refusing to append new data to it that'd be older.", f->path);</div> <div> return -ETXTBSY;</div> <div> }</div> <br> </span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">```</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;"><br> </span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> My thinking goes like this (assume start = now = 0):</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">1) A new journal is created with </span><span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">f->header->tail_entry_realtime = start</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 2) We process appending a new message whose `realtime = start+14s`</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 3) We perform the above check, passing it because 0 > now is false</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 4) We update the journal file header with the realtime from the message: <span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 13.3333px; font-style: normal; font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal;">f->header->tail_entry_realtime = start+14s</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 5) Wait 10 seconds, now = 10</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 6) We received a new message with a realtime = now+14s</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 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.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 8) We rotate the logs</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 9) Return to step 1.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> ---</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 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.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> I can only think of one practicable solutions, and that is to c<span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">hange the check so that it's comparing the f->header->tail_entry_realtime and the realtime of the message that's </span><span style="color: rgb(0, 0, 0); font-family: "Courier New", monospace; font-size: 10pt;">being logged.</span></div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 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.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> 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.</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> <br> </div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> Cheers,</div> <div style="font-family: "Courier New", monospace; font-size: 10pt; color: rgb(0, 0, 0);"> M</div> </body> </html>