From: Zbigniew Jędrzejewski-Szmek Date: Wed, 12 Jun 2024 09:55:14 +0000 (+0200) Subject: manager: add structured log message about clock bump X-Git-Tag: v257-rc1~1133^2~1 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=e0c7c9a00d529254c07659d094dd5e91730674bd;p=thirdparty%2Fsystemd.git 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 3c9a6860dab..e731d577e81 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 75039e9fcd4..a88997bddcd 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 8957d61b8b7..49d57afa9a6 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 cbd0e6663e5..a1b63038c45 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)));