timesyncd: write structured log messages whenever we bump the clock based on disk timestamp

It's useful being able to easily detect if a disk-based clock bump was
done, let's make it a structure message, the same way as acquiring an
NTP fix already is.

Also, set the clock to 1 µs further than the timestamp from the disk,
after all we know that that timestamp was current when it was written,
hence it can't be the right one right now anymore.

3 files changed, 27 insertions, 8 deletions

diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in
index 8d1812afcf..975e77fcec 100644
--- a/catalog/systemd.catalog.in
+++ b/catalog/systemd.catalog.in
@@ -528,6 +528,15 @@ Support: %SUPPORT_URL%
 For the first time during the current boot an NTP synchronization has been
 acquired and the local system clock adjustment has been initiated.
 
+-- 7db73c8af0d94eeb822ae04323fe6ab6
+Subject: Initial clock bump
+Defined-By: systemd
+Support: %SUPPORT_URL%
+
+The system clock has been advanced based on a timestamp file on disk, in order
+to ensure it remains roughly monotonic – even across reboots – if an RTC is not
+available or is unreliable.
+
 -- 3f7d5ef3e54f4302b4f0b143bb270cab
 Subject: TPM PCR Extended
 Defined-By: systemd
diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h
index 51241c9426..00fdbad2c5 100644
--- a/src/systemd/sd-messages.h
+++ b/src/systemd/sd-messages.h
@@ -183,6 +183,9 @@ _SD_BEGIN_DECLARATIONS;
 #define SD_MESSAGE_TIME_SYNC                          SD_ID128_MAKE(7c,8a,41,f3,7b,76,49,41,a0,e1,78,0b,1b,e2,f0,37)
 #define SD_MESSAGE_TIME_SYNC_STR                      SD_ID128_MAKE_STR(7c,8a,41,f3,7b,76,49,41,a0,e1,78,0b,1b,e2,f0,37)
 
+#define SD_MESSAGE_TIME_BUMP                          SD_ID128_MAKE(7d,b7,3c,8a,f0,d9,4e,eb,82,2a,e0,43,23,fe,6a,b6)
+#define SD_MESSAGE_TIME_BUMP_STR                      SD_ID128_MAKE_STR(7d,b7,3c,8a,f0,d9,4e,eb,82,2a,e0,43,23,fe,6a,b6)
+
 #define SD_MESSAGE_SHUTDOWN_SCHEDULED                 SD_ID128_MAKE(9e,70,66,27,9d,c8,40,3d,a7,9c,e4,b1,a6,90,64,b2)
 #define SD_MESSAGE_SHUTDOWN_SCHEDULED_STR             SD_ID128_MAKE_STR(9e,70,66,27,9d,c8,40,3d,a7,9c,e4,b1,a6,90,64,b2)
 
diff --git a/src/timesync/timesyncd.c b/src/timesync/timesyncd.c
index 887b323d96..709c64375e 100644
--- a/src/timesync/timesyncd.c
+++ b/src/timesync/timesyncd.c
@@ -5,6 +5,7 @@
 
 #include "sd-daemon.h"
 #include "sd-event.h"
+#include "sd-messages.h"
 
 #include "capability-util.h"
 #include "clock-util.h"
@@ -69,16 +70,22 @@ static int load_clock_timestamp(uid_t uid, gid_t gid) {
 
 settime:
         ct = now(CLOCK_REALTIME);
-        if (ct < min) {
-                char date[FORMAT_TIMESTAMP_MAX];
-
-                log_info("System clock time unset or jumped backwards, restoring from recorded timestamp: %s",
-                         format_timestamp(date, sizeof(date), min));
-
-                if (clock_settime(CLOCK_REALTIME, TIMESPEC_STORE(min)) < 0)
-                        log_error_errno(errno, "Failed to restore system clock, ignoring: %m");
+        if (ct > min)
+                return 0;
+
+        /* Not that it matters much, but we actually restore the clock to n+1 here rather than n, simply
+         * because we read n as time previously already and we want to progress here, i.e. not report the
+         * same time again. */
+        if (clock_settime(CLOCK_REALTIME, TIMESPEC_STORE(min+1)) < 0) {
+                log_warning_errno(errno, "Failed to restore system clock, ignoring: %m");
+                return 0;
         }
 
+        log_struct(LOG_INFO,
+                   "MESSAGE_ID=" SD_MESSAGE_TIME_BUMP_STR,
+                   "REALTIME_USEC=" USEC_FMT, min+1,
+                   LOG_MESSAGE("System clock time unset or jumped backwards, restored from recorded timestamp: %s",
+                               FORMAT_TIMESTAMP(min+1)));
         return 0;
 }