timesyncd: generate a structure log message the first time we set the clock correctly

poettering · poettering · commit b016e77efd5e · 2022-03-18T23:54:05.000+01:00
Usecase: later on we can use this to retroactively adjust log output in
journalctl or similar on systems lacking an RTC: we just have to search
for this sructured log message that indicates the first sync point and
can then retroactively adjust the incorrect timestamps collected before
that.
diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in
@@ -526,3 +526,11 @@ be updated to operate in a hotplug fashion without depending on
 systemd-udev-settle.service:
 
     @OFFENDING_UNITS@
+
+-- 7c8a41f37b764941a0e1780b1be2f037
+Subject: Initial clock synchronization
+Defined-By: systemd
+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.
diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h
@@ -200,6 +200,9 @@ _SD_BEGIN_DECLARATIONS;
 #define SD_MESSAGE_SYSTEMD_UDEV_SETTLE_DEPRECATED_STR \
                                           SD_ID128_MAKE_STR(1c,04,54,c1,bd,22,41,e0,ac,6f,ef,b4,bc,63,14,33)
 
+#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)
+
 _SD_END_DECLARATIONS;
 
 #endif
diff --git a/src/timesync/timesyncd-manager.c b/src/timesync/timesyncd-manager.c
@@ -11,6 +11,7 @@
 #include <sys/types.h>
 
 #include "sd-daemon.h"
+#include "sd-messages.h"
 
 #include "alloc-util.h"
 #include "dns-domain.h"
@@ -615,6 +616,17 @@ static int manager_receive_response(sd_event_source *source, int fd, uint32_t re
                 (void) sd_notifyf(false, "STATUS=Initial synchronization to time server %s (%s).", strna(pretty), m->current_server_name->string);
         }
 
+        if (!spike && !m->synchronized) {
+                m->synchronized = true;
+
+                log_struct(LOG_INFO,
+                           LOG_MESSAGE("Initial clock synchronization to %s.", FORMAT_TIMESTAMP_STYLE(dts.realtime, TIMESTAMP_US)),
+                           "MESSAGE_ID=" SD_MESSAGE_TIME_SYNC_STR,
+                           "MONOTONIC_USEC=" USEC_FMT, dts.monotonic,
+                           "REALTIME_USEC=" USEC_FMT, dts.realtime,
+                           "BOOTIME_USEC=" USEC_FMT, dts.boottime);
+        }
+
         r = manager_arm_timer(m, m->poll_interval_usec);
         if (r < 0)
                 return log_error_errno(r, "Failed to rearm timer: %m");
@@ -1110,6 +1122,12 @@ int manager_new(Manager **ret) {
 
         (void) sd_event_set_watchdog(m->event, true);
 
+        /* Load previous synchronization state */
+        r = access("/run/systemd/timesync/synchronized", F_OK);
+        if (r < 0 && errno != ENOENT)
+                log_debug_errno(errno, "Failed to determine whether /run/systemd/timesync/synchronized exists, ignoring: %m");
+        m->synchronized = r >= 0;
+
         r = sd_resolve_default(&m->resolve);
         if (r < 0)
                 return r;
diff --git a/src/timesync/timesyncd-manager.h b/src/timesync/timesyncd-manager.h
@@ -104,6 +104,9 @@ struct Manager {
         struct timespec origin_time, dest_time;
         bool spike;
 
+        /* Indicates whether we ever managed to set the local clock from NTP */
+        bool synchronized;
+
         /* save time event */
         sd_event_source *event_save_time;
         usec_t save_time_interval_usec;
