From e0c7c9a00d529254c07659d094dd5e91730674bd Mon Sep 17 00:00:00 2001 From: =?utf8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Wed, 12 Jun 2024 11:55:14 +0200 Subject: [PATCH] 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. --- catalog/systemd.catalog.in | 9 -------- catalog/systemd.pl.catalog.in | 10 --------- src/core/clock-warp.c | 39 +++++++++++++++++++++++++++-------- src/timesync/timesyncd.c | 1 + 4 files changed, 31 insertions(+), 28 deletions(-) diff --git a/catalog/systemd.catalog.in b/catalog/systemd.catalog.in index 3c9a6860da..e731d577e8 100644 --- 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 75039e9fcd..a88997bddc 100644 --- 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 8957d61b8b..49d57afa9a 100644 --- a/src/core/clock-warp.c +++ b/src/core/clock-warp.c @@ -3,6 +3,8 @@ #include #include +#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 cbd0e6663e..a1b63038c4 100644 --- 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))); -- 2.25.1