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
One ID for the success case, with WATCHDOG_DEVICE= showing the device,
and one ID for the failure case, with WATCHDOG_DEVICE= if configured,
and ERRNO= set automatically.
We need to retry the open attempts for the watchdog, because the device becomes
available asynchronously.
The watchdog is opened in two places:
- in pid1 in the main loop. The loop has a ratelimit, but during a boot we
iterate in it fairly quickly. On my test VM with 'iTCO_wdt', version 2:
$ journalctl -b --grep 'Failed to open any watchdog' | wc -l
3398
After the device has been processed by udev, it is initialized successfully.
- in shutdown. In that case, we most likely don't need to try more than once,
because we mostly care about the case where the watchdog device was present
and configured previously. But in principle it is possible that we might
attempt shutdown while the machine was initializing, so we don't want to
disable retries. Nevertheless, watchdog_ping() is called from a loop that
might be fairly tight, so we could end up trying to reopen the device fairly
often. This probably doesn't matter *too* much, but it's still ugly to try to
open the device without any ratelimit.
Usually the watchdog timeout would be set to something like 30 s or a few
minutes. OTOH, on my VM, the device becomes avaiable at 4.35 s after boot. So
let's use 5 s or half the watchdog timeout, whatever is smaller, as the
interval.
I think we need to log at some point if the user configured a watchdog device,
but no devices were found. We can't log ENOENT immediately, because the device
may likely appear during boot. So wait until the end of the initial transaction
and log then.
If we failed to open the watchdog device for any reason, we'd only log at debug
level. This seems iffy: if the user configured a timeout for the watchdog, we
should report when we can't set it up. ENOENT is still logged at debug level
only, since it's somewhat expected to have a watchdog timeout set up, even for
systems which don't have a watchdog, or the device might appear later.
If the device doesn't support WDIOC_GETSUPPORT, still log that we opened a
device.
No change in behaviour, except for the log level threshold. As a side effect,
the reason why we failed to open the device is now stored in watchdog_fd
(previously it was -1 always), but this isn't used for anything.
This is not a hot path, but let's move the variables to the
minimal scope in which they are needed.
Also, all functions which call watchdog_open() check for fd < 0 first,
so change the conditional return into an assert.
When we open a watchdog fresh we have never pinged it, hence reset the
ping timestamp explicitly, so that it is not only reset the first time
we open the device, but all times.
- drop unnecessary SYNTHETIC_ERRNO() when the logger does not propagate
error code,
- drop unnecessary '%m' in error message when the error code is
specified with SYNTHETIC_ERRNO(),
- add missing full stop at the end of log message,
- use RET_GATHER(),
- add missing ", ignoring.",
- upeercase the first letter, etc., etc...
This makes sure we mention the word "watchdog" in every log message
related to the watchdog.
Also, this uses the expression "hardware timeout" when referring to the
primary timeout of the watchdog, as opposed to the "pretimeout".
(Not ideal wording I know, but it's preexisting to some point, I just
continued it. I think it's OK though, in particular to underline the
difference to the software watchdog logic we implement via WATCHDOG= in
sd_notify().)
Fixes: #31662
In some rare cases, a watchdog driver might neither be able to change
the watchdog timeout value, nor read it from the hardware at runtime.
With an otherwise functional watchdog setup, this constellation worked
until systemd v249. Since then, systemd ends up ignoring the timeout
defined by the system.conf and rather uses USEC_INFINITY. Consequently,
the watchdog is not pinged anymore and eventually resets the system.
We therefore want to ensure that the system keeps running with the
originally configured timeout.
If we change the watchdog device we should disarm the old one first.
Similar, if we open the watchdog, but then fail setting it up, disarm it
before closing it again.
-1 was used everywhere, but -EBADF or -EBADFD started being used in various
places. Let's make things consistent in the new style.
Note that there are two candidates:
EBADF 9 Bad file descriptor
EBADFD 77 File descriptor in bad state
Since we're initializating the fd, we're just assigning a value that means
"no fd yet", so it's just a bad file descriptor, and the first errno fits
better. If instead we had a valid file descriptor that became invalid because
of some operation or state change, the other errno would fit better.
In some places, initialization is dropped if unnecessary.
Follow-up for 10f3f4ed01.
We already have RuntimeWatchdogUSec or friends. Let's not introduce
redundant properties.
Also, drop the const qualifier for WatchdogLastPingTimestamp, as they
are actually not constant.
Let's raise our supported baseline a bit: CLOCK_BOOTTIME started to work
with timerfd in kernel 3.15 (i.e. back in 2014), let's require support
for it now.
This will raise our baseline only modestly from 3.13 → 3.15.
Check and log the default pretimeout governor configured in the kernel.
The pretimeout will not work unless at least one governor is available
and configured. This requires loading a kernel module manually.
Add support for managing and configuring watchdog pretimeout values if
the watchdog hardware supports it. The ping interval is adjusted to
account for a pretimeout so that it will still ping at half the timeout
interval before a pretimeout event would be triggered. By default the
pretimeout defaults to 0s or disabled.
The RuntimeWatchdogPreSec config option is added to allow the pretimeout
to be specified (similar to RuntimeWatchdogSec). The
RuntimeWatchdogPreUSec dbus property is added to override the pretimeout
value at runtime (similar to RuntimeWatchdogUSec). Setting the
pretimeout to 0s will disable the pretimeout.
Since version 4.5, the max possible timeout is UINT_MAX / 1000 since it
does calculations in milliseconds. A small helper function is added to
make this conversion and saturation and will be used more in the next
commit.
Also document the usage of signed integers by the kernel userspace API.
Coverity (and I, initially) get really confused about "fn"'s validity
here. it doesn't grok that free_and_strdup() is actually a NOP in case
the string isn't changed, and assumes it always invalidates the
specified buffer, which it doesn't do though.
Follow-up for: f4b1a6b641
If watchdog_set_device() is not called before open_watchdog() then
'watchdog_device' remains 'NULL' while the device is open.
As a result, the "same device" check in watchdog_set_device() does not work
correctly: If no device is specified (e.g. from watchdog_free_device())
then the current fd is not closed.
Fix this by setting 'watchdog_device' to the correct device during
open_watchdog()
If an error happened while the timeout value was being programmed, the error
was ignored and the watchdog module used the new timeout value whereas the
watchdog device was left with the previous one.
Now in cases of error, the device is now disabled and closed if it wasn't
opened already otherwise the previous timeout value is kept so the device is
still pinged at correct intervals.
Passing 0 meant "disable the watchdog although still kept it opened". However
this case didn't seem to be useful especially since PID1 closes the device if
it is passed the nul timeout.
Hence let's change the meaning of watchdog_setup(0) to match PID1's behavior
which allows to simplify the code a bit.
Hence this patch also drops enable_watchdog().
This patch changes the meaning of USEC_INFINITY value for the watchdog
module.
Previously passing this value was a NOP. It now has a special meaning: it
requests the watchdog module to read the programmed timeout value and reuse it
for pinging the device.
This is mostly useful when the watchdog is started by the firmware and there's
no way to reconfigure the timeout with a different value
afterwards. "RuntimeWatchdogSec=infinity" in system.conf can now be used rather
than putting an arbitrary value that PID1 will fail to set (even if it still
felt back to the programmed timeout).
Please note that "infinity" is not supposed to restore the default value of the
firmware. If the value is changed after booting then "infinity" would simply
reuse the current programmed value. IOW it's a NOP unless the watchdog was
previously closed and in that case it will be reopened and the last programmed
value reused.
Daan De Meyer
Yu Watanabe
Zbigniew Jędrzejewski-Szmek
Lennart Poettering
Holger Assmann
Jan Janssen
Luca Boccassi
Curtis Klein
Curtis Klein
Michael Olbrich
Franck Bui