manager: add structured log message about clock bump

Requested in https://github.com/systemd/systemd/pull/33214#discussion_r1630251308.
Also, reword error messages a bit. When /usr/lib/clock-epoch was introduced,
"build time" stopped being acurate. Just say "epoch" instead.

The same message ID is used in the manager and timesyncd. The event is
essentially equivalent for the user, and it seems reasonable that to search for
both at the same time.

The catalog entry is dropped. It provided almost no additional information above
the message. When the same message ID is now applied to messages from PID1 and
timesyncd, and the clock can be both advanced and rewound, it becomes very hard
to make the catalog entry provide something useful, because catalog entries don't
allow conditionalization.

diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in
index 3c9a6860dab88712bc0eb47322b1d34259b33e20..e731d577e8155beda08fe4f3a22d7f1500edeb0c 100644 (file)
--- a/catalog/systemd.catalog.in
+++ b/catalog/systemd.catalog.in
@@ -704,15 +704,6 @@ 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/catalog/systemd.pl.catalog.in b/catalog/systemd.pl.catalog.in
index 75039e9fcd4e89f53dc60fa01c023cf9d8b6ec6e..a88997bddcd8ea01acf2eac08b7f203b6cffcbcc 100644 (file)
--- a/catalog/systemd.pl.catalog.in
+++ b/catalog/systemd.pl.catalog.in
@@ -723,16 +723,6 @@ Support: %SUPPORT_URL%
 Po raz pierwszy podczas obecnego uruchomienia uzyskano synchronizację NTP
 i zainicjowano regulację lokalnego zegara systemowego.
 
--- 7db73c8af0d94eeb822ae04323fe6ab6
-Subject: Początkowe przestawienie zegara
-Defined-By: systemd
-Support: %SUPPORT_URL%
-
-Przestawiono zegar systemowy na podstawie pliku ze znacznikiem czasu na dysku
-w celu zapewnienia, że nadal jest w przybliżeniu monotoniczny — nawet między
-ponownymi uruchomieniami — jeśli zegar czasu rzeczywistego jest niedostępny
-lub zawodny.
-
 -- 3f7d5ef3e54f4302b4f0b143bb270cab
 Subject: Rozszerzono PCR układu TPM
 Defined-By: systemd

diff --git a/src/core/clock-warp.c b/src/core/clock-warp.c
index 8957d61b8b7a303fa9b87da7a2c45a438870478b..49d57afa9a66e72d809a865e35747b4bd7e0f273 100644 (file)
--- a/src/core/clock-warp.c
+++ b/src/core/clock-warp.c
@@ -3,6 +3,8 @@
 #include <sys/stat.h>
 #include <sys/time.h>
 
+#include "sd-messages.h"
+
 #include "clock-util.h"
 #include "clock-warp.h"
 #include "errno-util.h"
@@ -55,14 +57,33 @@ void clock_apply_epoch(bool allow_backwards) {
                 return;  /* Nothing to do. */
 
         r = RET_NERRNO(clock_settime(CLOCK_REALTIME, TIMESPEC_STORE(epoch_usec)));
-        if (r < 0 && advance)
-                return (void) log_error_errno(r, "Current system time is before build time, but cannot correct: %m");
-        else if (r < 0)
-                return (void) log_error_errno(r, "Current system time is further ahead than %s after build time, but cannot correct: %m",
-                                              FORMAT_TIMESPAN(CLOCK_VALID_RANGE_USEC_MAX, USEC_PER_DAY));
-        else if (advance)
-                log_info("System time was before build time, advanced clock.");
+        if (r < 0) {
+                if (advance)
+                        return (void) log_error_errno(r, "Current system time is before epoch, but cannot correct: %m");
+                else
+                        return (void) log_error_errno(r, "Current system time is further ahead than %s after epoch, but cannot correct: %m",
+                                                      FORMAT_TIMESPAN(CLOCK_VALID_RANGE_USEC_MAX, USEC_PER_DAY));
+        }
+
+        const char *from =
+                epoch_usec == (usec_t) TIME_EPOCH * USEC_PER_SEC ? "built-in epoch" :
+                epoch_usec == timesyncd_usec ? "timestamp on "TIMESYNCD_CLOCK_FILE :
+                "timestamp on "EPOCH_CLOCK_FILE;
+        if (advance)
+                log_struct(LOG_INFO,
+                           "MESSAGE_ID=" SD_MESSAGE_TIME_BUMP_STR,
+                           "REALTIME_USEC=" USEC_FMT, epoch_usec,
+                           "DIRECTION=forwards",
+                           LOG_MESSAGE("System time advanced to %s: %s",
+                                       from,
+                                       FORMAT_TIMESTAMP(epoch_usec)));
         else
-                log_info("System time was further ahead than %s after build time, reset clock to build time.",
-                         FORMAT_TIMESPAN(CLOCK_VALID_RANGE_USEC_MAX, USEC_PER_DAY));
+                log_struct(LOG_INFO,
+                           "MESSAGE_ID=" SD_MESSAGE_TIME_BUMP_STR,
+                           "REALTIME_USEC=" USEC_FMT, epoch_usec,
+                           "DIRECTION=backwards",
+                           LOG_MESSAGE("System time was further ahead than %s after %s, clock reset to %s",
+                                       FORMAT_TIMESPAN(CLOCK_VALID_RANGE_USEC_MAX, USEC_PER_DAY),
+                                       from,
+                                       FORMAT_TIMESTAMP(epoch_usec)));
 }

diff --git a/src/timesync/timesyncd.c b/src/timesync/timesyncd.c
index cbd0e6663e55731f5024163507dd349666381e9c..a1b63038c45491903cc86dc9aae4d3564cbed1c8 100644 (file)
--- a/src/timesync/timesyncd.c
+++ b/src/timesync/timesyncd.c
@@ -126,6 +126,7 @@ static int load_clock_timestamp(uid_t uid, gid_t gid) {
         log_struct(LOG_INFO,
                    "MESSAGE_ID=" SD_MESSAGE_TIME_BUMP_STR,
                    "REALTIME_USEC=" USEC_FMT, epoch + 1,
+                   "DIRECTION=forwards",
                    LOG_MESSAGE("System clock time advanced to %s: %s",
                                epoch > TIME_EPOCH * USEC_PER_SEC ? "recorded timestamp" : "built-in epoch",
                                FORMAT_TIMESTAMP(epoch + 1)));