From ab596e4cde5d4b55be5182a8d5554e3e97366131 Mon Sep 17 00:00:00 2001 From: =?utf8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Fri, 21 Mar 2025 14:39:50 +0100 Subject: [PATCH] shared/watchdog: give up after a few failed pings Closes https://github.com/systemd/systemd/issues/35405. Apparently some watchdog devices can be opened, but then the pings start failing after some time. Since the timestamp of the last successful ping is not updated, we try to ping again immediately, causing a busy loop and excessive logging. After trying a few different approaches to fit this into the existing framework without changing the logic too much, I settled on an approach with a second timestamp. In particular, the timestamp of the last successful ping is public, exposed as WatchdogLastPingTimestamp over dbus. It'd be wrong to redefine this to mean the last ping *attempt*. So we need a second timestamp in some form. Also, if we give up on pinging, we probably should attempt to disarm the watchdog. It's possible that the pinging fails, but the watchdog would still fire. I don't think we want that, since it seems that our internal loop is working, it's just the watchdog that is broken. Structured message with SD_MESSAGE_WATCHDOG_PING_FAILED is logged if we fail to ping. I tested this by attaching gdb to pid 1 and calling close(watchdog_fd). We get a bunch of warning messages and then an attempt to close the watchdog: Mar 21 15:46:17 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:20 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:23 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:26 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:29 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:32 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:35 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:37 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:40 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:43 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:46 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:49 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:52 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:55 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0: Bad file descriptor Mar 21 15:46:58 fedora systemd[1]: Failed to ping hardware watchdog /dev/watchdog0, closing watchdog after 15 attempts: Bad file descriptor Mar 21 15:46:58 fedora systemd[1]: Failed to disable hardware watchdog, ignoring: Bad file descriptor Mar 21 15:46:58 fedora systemd[1]: Failed to disarm watchdog timer, ignoring: Bad file descriptor --- src/core/main.c | 6 +-- src/core/manager.c | 2 +- src/shared/watchdog.c | 86 +++++++++++++++++++++++++++------------ src/shared/watchdog.h | 2 +- src/systemd/sd-messages.h | 3 ++ src/test/test-watchdog.c | 4 +- 6 files changed, 70 insertions(+), 33 deletions(-) diff --git a/src/core/main.c b/src/core/main.c index bca6c96b4e1..23ce9aa92cf 100644 --- a/src/core/main.c +++ b/src/core/main.c @@ -1985,9 +1985,9 @@ static int do_reexecute( assert(saved_rlimit_memlock); assert(ret_error_message); - /* Close and disarm the watchdog, so that the new instance can reinitialize it, but doesn't get - * rebooted while we do that */ - watchdog_close(true); + /* Close and disarm the watchdog, so that the new instance can reinitialize it, but the machine + * doesn't get rebooted while we do that. */ + watchdog_close(/* disarm= */ true); if (!switch_root_dir && objective == MANAGER_SOFT_REBOOT) { /* If no switch root dir is specified, then check if /run/nextroot/ qualifies and use that */ diff --git a/src/core/manager.c b/src/core/manager.c index 6d20cf9423f..45f3464dd44 100644 --- a/src/core/manager.c +++ b/src/core/manager.c @@ -3391,7 +3391,7 @@ int manager_loop(Manager *m) { continue; /* Sleep for watchdog runtime wait time */ - r = sd_event_run(m->event, watchdog_runtime_wait()); + r = sd_event_run(m->event, watchdog_runtime_wait(/* divisor= */ 2)); if (r < 0) return log_error_errno(r, "Failed to run event loop: %m"); } diff --git a/src/shared/watchdog.c b/src/shared/watchdog.c index 6828a22b425..5b3f950b80e 100644 --- a/src/shared/watchdog.c +++ b/src/shared/watchdog.c @@ -23,7 +23,9 @@ static int watchdog_fd = -EBADF; static char *watchdog_device = NULL; static usec_t watchdog_timeout = 0; /* 0 → close device and USEC_INFINITY → don't change timeout */ static usec_t watchdog_pretimeout = 0; /* 0 → disable pretimeout and USEC_INFINITY → don't change pretimeout */ -static usec_t watchdog_last_ping = USEC_INFINITY; +static usec_t watchdog_last_good_ping = USEC_INFINITY; +static usec_t watchdog_last_bad_ping = USEC_INFINITY; +static unsigned watchdog_bad_pings = 0; static bool watchdog_supports_pretimeout = false; /* Depends on kernel state that might change at runtime */ static char *watchdog_pretimeout_governor = NULL; @@ -36,6 +38,11 @@ static char *watchdog_pretimeout_governor = NULL; */ #define WATCHDOG_TIMEOUT_MAX_SEC (CONST_MIN(UINT_MAX/1000U, (unsigned)INT_MAX)) +/* How many times to ping the watchdog in a single burst. */ +#define WATCHDOG_PING_BURST 3 +/* How many times to ping the watchdog in total before giving up on it. */ +#define WATCHDOG_MAX_FAILED_PINGS 15 + #define WATCHDOG_GOV_NAME_MAXLEN 20 /* From the kernel watchdog driver */ static int saturated_usec_to_sec(usec_t val) { @@ -193,7 +200,7 @@ static int watchdog_set_pretimeout(void) { } usec_t watchdog_get_last_ping(clockid_t clock) { - return map_clock_usec(watchdog_last_ping, CLOCK_BOOTTIME, clock); + return map_clock_usec(watchdog_last_good_ping, CLOCK_BOOTTIME, clock); } static int watchdog_ping_now(void) { @@ -202,12 +209,35 @@ static int watchdog_ping_now(void) { assert(watchdog_fd >= 0); r = RET_NERRNO(ioctl(watchdog_fd, WDIOC_KEEPALIVE, 0)); - if (r < 0) - return log_warning_errno(r, "Failed to ping hardware watchdog, ignoring: %m"); - - watchdog_last_ping = now(CLOCK_BOOTTIME); + if (r < 0) { + watchdog_last_bad_ping = now(CLOCK_BOOTTIME); + if (++ watchdog_bad_pings >= WATCHDOG_MAX_FAILED_PINGS) { + log_struct_errno(LOG_ERR, r, + LOG_MESSAGE("Failed to ping hardware watchdog %s, closing watchdog after %u attempts: %m", + watchdog_device, watchdog_bad_pings), + "MESSAGE_ID=" SD_MESSAGE_WATCHDOG_PING_FAILED_STR, + "WATCHDOG_DEVICE=%s", watchdog_device); + watchdog_timeout = USEC_INFINITY; + watchdog_close(/* disarm= */ true); + } else + log_struct_errno(LOG_WARNING, r, + LOG_MESSAGE("Failed to ping hardware watchdog %s: %m", + watchdog_device), + "MESSAGE_ID=" SD_MESSAGE_WATCHDOG_PING_FAILED_STR, + "WATCHDOG_DEVICE=%s", watchdog_device); + } else { + watchdog_last_good_ping = now(CLOCK_BOOTTIME); + if (watchdog_bad_pings > 0) { + log_struct(LOG_INFO, + LOG_MESSAGE("Succesfullly pinged hardware watchdog %s after %u attempts: %m", + watchdog_device, watchdog_bad_pings + 1), + "WATCHDOG_DEVICE=%s", watchdog_device); + watchdog_bad_pings = 0; + watchdog_last_bad_ping = USEC_INFINITY; + } + } - return 0; + return r; } static int watchdog_update_pretimeout(void) { @@ -358,7 +388,8 @@ static int watchdog_open(bool ignore_ratelimit) { watchdog_device ? " " : "", strempty(watchdog_device)); - watchdog_last_ping = USEC_INFINITY; + watchdog_last_good_ping = watchdog_last_bad_ping = USEC_INFINITY; + watchdog_bad_pings = 0; r = RET_NERRNO(ioctl(watchdog_fd, WDIOC_GETSUPPORT, &ident)); if (r < 0) @@ -410,7 +441,7 @@ int watchdog_setup(usec_t timeout) { * it's a nop if the device is already opened). */ if (timeout == 0) { - watchdog_close(true); + watchdog_close(/* disarm= */ true); return 0; } @@ -454,6 +485,10 @@ int watchdog_setup_pretimeout_governor(const char *governor) { } static usec_t watchdog_calc_timeout(void) { + /* If we failed to many times, don't schedule the next attempt at all. */ + if (watchdog_bad_pings >= WATCHDOG_MAX_FAILED_PINGS) + return 0; + /* Calculate the effective timeout which accounts for the watchdog * pretimeout if configured and supported. */ if (watchdog_supports_pretimeout && timestamp_is_set(watchdog_pretimeout) && watchdog_timeout >= watchdog_pretimeout) @@ -462,20 +497,26 @@ static usec_t watchdog_calc_timeout(void) { return watchdog_timeout; } -usec_t watchdog_runtime_wait(void) { +usec_t watchdog_runtime_wait(unsigned divisor) { usec_t timeout = watchdog_calc_timeout(); if (!timestamp_is_set(timeout)) return USEC_INFINITY; - /* Sleep half the watchdog timeout since the last successful ping at most */ - if (timestamp_is_set(watchdog_last_ping)) { + /* Sleep watchdog timeout / divisor since the last successful ping attempt at most, + * or the fifth of that if the ping failed. */ + + usec_t ts = MAX(timestamp_is_set(watchdog_last_good_ping) ? watchdog_last_good_ping : 0u, + timestamp_is_set(watchdog_last_bad_ping) ? watchdog_last_bad_ping : 0u); + if (ts > 0) { usec_t ntime = now(CLOCK_BOOTTIME); + if (ts == watchdog_last_bad_ping) + divisor *= 5; - assert(ntime >= watchdog_last_ping); - return usec_sub_unsigned(watchdog_last_ping + timeout/2, ntime); + assert(ntime >= ts); + return usec_sub_unsigned(ts + timeout / divisor, ntime); } - return timeout / 2; + return timeout / divisor; } int watchdog_ping(void) { @@ -486,17 +527,10 @@ int watchdog_ping(void) { /* open_watchdog() will automatically ping the device for us if necessary */ return watchdog_open(/* ignore_ratelimit= */ false); - /* Never ping earlier than watchdog_timeout/4 and try to ping - * by watchdog_timeout/2 plus scheduling latencies at the latest */ - if (timestamp_is_set(watchdog_last_ping)) { - usec_t ntime = now(CLOCK_BOOTTIME), - timeout = watchdog_calc_timeout(); - - assert(ntime >= watchdog_last_ping); - - if (ntime - watchdog_last_ping < timeout/4) - return 0; - } + /* Ping approximately watchdog_timeout/4 after a successful ping, or even less than that + * after an unsuccessful ping. */ + if (watchdog_runtime_wait(/* divisor= */ 4) > 0) + return 0; return watchdog_ping_now(); } diff --git a/src/shared/watchdog.h b/src/shared/watchdog.h index da63730a5ca..c0fcccbd073 100644 --- a/src/shared/watchdog.h +++ b/src/shared/watchdog.h @@ -15,7 +15,7 @@ int watchdog_setup_pretimeout_governor(const char *governor); int watchdog_ping(void); void watchdog_report_if_missing(void); void watchdog_close(bool disarm); -usec_t watchdog_runtime_wait(void); +usec_t watchdog_runtime_wait(unsigned divisor); static inline void watchdog_free_device(void) { (void) watchdog_set_device(NULL); diff --git a/src/systemd/sd-messages.h b/src/systemd/sd-messages.h index c35b1bfdec4..502a2e5d5ae 100644 --- a/src/systemd/sd-messages.h +++ b/src/systemd/sd-messages.h @@ -262,6 +262,9 @@ _SD_BEGIN_DECLARATIONS; #define SD_MESSAGE_WATCHDOG_OPEN_FAILED SD_ID128_MAKE(37,5a,c1,51,ef,9d,4d,e3,90,68,b3,ef,bf,ed,0c,ee) #define SD_MESSAGE_WATCHDOG_OPEN_FAILED_STR SD_ID128_MAKE_STR(37,5a,c1,51,ef,9d,4d,e3,90,68,b3,ef,bf,ed,0c,ee) +#define SD_MESSAGE_WATCHDOG_PING_FAILED SD_ID128_MAKE(87,39,78,9e,ca,06,43,25,af,15,a8,ed,0e,cf,c5,56) +#define SD_MESSAGE_WATCHDOG_PING_FAILED_STR SD_ID128_MAKE_STR(87,39,78,9e,ca,06,43,25,af,15,a8,ed,0e,cf,c5,56) + #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/test/test-watchdog.c b/src/test/test-watchdog.c index 1eb284cd29d..67e6581cfb0 100644 --- a/src/test/test-watchdog.c +++ b/src/test/test-watchdog.c @@ -23,7 +23,7 @@ int main(int argc, char *argv[]) { log_warning_errno(r, "Failed to open watchdog: %m"); for (unsigned i = 0; i < count; i++) { - timeout = watchdog_runtime_wait(); + timeout = watchdog_runtime_wait(/* divisor= */ 2); log_info("Sleeping %s…", FORMAT_TIMESPAN(timeout, USEC_PER_SEC)); usleep_safe(timeout); log_info("Pinging..."); @@ -32,6 +32,6 @@ int main(int argc, char *argv[]) { log_warning_errno(r, "Failed to ping watchdog: %m"); } - watchdog_close(true); + watchdog_close(/* disarm= */ true); return 0; } -- 2.47.3