diff --git a/changes-entries/systemd-watchdog.txt b/changes-entries/systemd-watchdog.txt new file mode 100644 index 00000000000..0145c1cc00e --- /dev/null +++ b/changes-entries/systemd-watchdog.txt @@ -0,0 +1,4 @@ + *) mod_systemd: Support the systemd watchdog, sending the keep-alive + notification if the service unit sets WatchdogSec=. The notification + is sent every ten seconds, so a shorter WatchdogSec cannot be met and + is warned about at startup. [Joe Orton] diff --git a/docs/manual/mod/mod_systemd.xml b/docs/manual/mod/mod_systemd.xml index 2fe5a458df7..3db140d584f 100644 --- a/docs/manual/mod/mod_systemd.xml +++ b/docs/manual/mod/mod_systemd.xml @@ -81,6 +81,31 @@ WantedBy=multi-user.target module="core">ExtendedStatus is not disabled in the configuration, run-time load and request statistics are made available in the systemctl status output.

+ +

The systemd watchdog is supported. If the service unit sets + WatchdogSec=, the parent process sends the keep-alive + notification which tells systemd the server is still alive; a server + which stops sending it is terminated and, with a suitable + Restart= setting, restarted. The notification is sent + while the configuration is being read and again once it is loaded, so + that a reload is covered, and periodically from the parent process + while the server runs.

+ +

That periodic notification is sent about every ten seconds, which + is how often the parent process runs the hook it is sent from. A + WatchdogSec= of less than twice that cannot be met, and + would have systemd terminating a server which is working normally; + such a setting is reported as a warning at startup. Use a + WatchdogSec= of at least 20 seconds.

+ + + Adding watchdog supervision to the unit above + 
+[Service]
+WatchdogSec=30
+Restart=on-failure
+
+ diff --git a/modules/arch/unix/mod_systemd.c b/modules/arch/unix/mod_systemd.c index 43b24ef2d0b..6c03acc3a35 100644 --- a/modules/arch/unix/mod_systemd.c +++ b/modules/arch/unix/mod_systemd.c @@ -52,10 +52,37 @@ static apr_uint64_t monotonic_usec(void) return (apr_uint64_t)ts.tv_sec * APR_USEC_PER_SEC + ts.tv_nsec / 1000; } +/* ap_run_monitor() is called once every INTERVAL_OF_WRITABLE_PROBES turns + * of the parent's one second loop in ap_wait_or_timeout(), so that is how + * often a keep-alive notification can be sent, and the shortest watchdog + * timeout which can be met is twice that: sd_watchdog_enabled(3) asks for + * a notification every half of the configured timeout. */ +#define WATCHDOG_INTERVAL_SEC (10) + +/* The WatchdogSec= of the service in microseconds, or zero if the service + * manager is not watching. Set in pre_config, before the first + * notification which could carry a keep-alive. */ +static apr_uint64_t watchdog_usec; + +/* A keep-alive assignment to paste into a notification, or nothing while + * the service manager is not asking for one. Sending WATCHDOG=1 when it + * is not expected is harmless, but saying so only when asked keeps what + * httpd reports the same as what the service was configured for. */ +static const char *watchdog_ping(void) +{ + return watchdog_usec ? "WATCHDOG=1\n" : ""; +} + static int systemd_pre_config(apr_pool_t *pconf, apr_pool_t *plog, apr_pool_t *ptemp) { - apr_uint64_t usec = monotonic_usec(); + apr_uint64_t usec = monotonic_usec(), wd_usec; + + /* Read afresh on each configuration load, since a restart unloads and + * loads the module again, and without unsetting it as server/listen.c + * does for $LISTEN_FDS, which would stop the keep-alive at the first + * reload. */ + watchdog_usec = sd_watchdog_enabled(0, &wd_usec) > 0 ? wd_usec : 0; /* A Type=notify-reload service ignores a reload notification which * does not say when it was sent. */ @@ -63,12 +90,14 @@ static int systemd_pre_config(apr_pool_t *pconf, apr_pool_t *plog, sd_notifyf(0, "RELOADING=1\n" "MONOTONIC_USEC=%" APR_UINT64_T_FMT "\n" - "STATUS=Reading configuration...\n", usec); + "%s" + "STATUS=Reading configuration...\n", usec, watchdog_ping()); } else { - sd_notify(0, - "RELOADING=1\n" - "STATUS=Reading configuration...\n"); + sd_notifyf(0, + "RELOADING=1\n" + "%s" + "STATUS=Reading configuration...\n", watchdog_ping()); } ap_extended_status = 1; return OK; @@ -121,8 +150,28 @@ static int systemd_post_config(apr_pool_t *pconf, apr_pool_t *plog, apr_pool_cleanup_register(pconf, NULL, systemd_stopping, apr_pool_cleanup_null); - sd_notify(0, "READY=1\n" - "STATUS=Configuration loaded.\n"); + /* A timeout the parent cannot meet would have the service manager + * killing a healthy server every WatchdogSec, so say so rather than + * leaving nothing in the log to explain it. */ + if (watchdog_usec + && watchdog_usec / 2 < (apr_uint64_t)WATCHDOG_INTERVAL_SEC + * APR_USEC_PER_SEC) { + ap_log_error(APLOG_MARK, APLOG_WARNING, 0, main_server, APLOGNO(10621) + "WatchdogSec is %" APR_UINT64_T_FMT "us, but keep-alive " + "notifications are sent from the parent process only " + "every %ds; configure a WatchdogSec of at least %ds or " + "the service will be killed while it is healthy", + watchdog_usec, WATCHDOG_INTERVAL_SEC, + 2 * WATCHDOG_INTERVAL_SEC); + } + + /* The keep-alive rides along with the notification which ends a + * reload: the configuration is read outside the parent's monitor loop, + * so nothing reports while it is being parsed, and the service manager + * keeps the timeout armed throughout. */ + sd_notifyf(0, "READY=1\n" + "%s" + "STATUS=Configuration loaded.\n", watchdog_ping()); return OK; } @@ -141,6 +190,12 @@ static int systemd_monitor(apr_pool_t *p, server_rec *s) apr_interval_time_t up_time; char bps[5]; + /* Before anything which might decline: reporting the server is alive + * does not depend on there being a status line to report with it. */ + if (watchdog_usec) { + sd_notify(0, "WATCHDOG=1\n"); + } + if (!ap_extended_status) { /* Nothing useful to report with ExtendedStatus disabled. */ return DECLINED; diff --git a/test/modules/arch/linux/README b/test/modules/arch/linux/README index 3894c6158fa..f8037431e91 100644 --- a/test/modules/arch/linux/README +++ b/test/modules/arch/linux/README @@ -17,15 +17,19 @@ to the service manager rather than to a client: activation and not loading it is what disables it. - ap_extended_status forced on in pre_config, so that the monitor hook has request counts to report. + - the watchdog keep-alive, WATCHDOG=1, sent while the service manager + asks for one. Which it does through the environment as well: + WatchdogSec= in the unit becomes $WATCHDOG_USEC, and $WATCHDOG_PID + names the process expected to report. None of that is observable over HTTP, so the tests observe it directly. How the tests run without systemd, and without privileges --------------------------------------------------------- There is no need for a service manager to exercise the protocol. Only -test_005 involves systemd at all; the rest run anywhere, and need nothing -from the systemd package beyond the libsystemd httpd itself is linked -against. +test_005, and the last test of test_006, involve systemd at all; the rest +run anywhere, and need nothing from the systemd package beyond the +libsystemd httpd itself is linked against. test_001_notify.py $NOTIFY_SOCKET is an ordinary AF_UNIX datagram socket the test binds itself (env.NotifyListener). @@ -51,6 +55,22 @@ against. distributions, and doing it directly needs no systemd tooling at all. + test_006_watchdog.py The keep-alive. Mostly the same stand-in socket, + with $WATCHDOG_USEC set in the environment httpd is + started with; env.ForegroundServer runs httpd in the + foreground where $WATCHDOG_PID can name it, which + apachectl cannot do for a parent it has not forked + yet. The last test uses a real unit with + WatchdogSec=, where systemd's own + WatchdogTimestampMonotonic is the evidence that the + pings arrived. + + The keep-alive is sent from the monitor hook, so it + is only as frequent as that hook is: about every ten + seconds. A WatchdogSec shorter than twice that + cannot be met, and mod_systemd says so (AH10621) + rather than letting a healthy server be killed. + test_005_service.py The real thing: a transient Type=notify unit run with "systemd-run --user". This is what checks that systemd holds the unit in "activating" until READY=1 diff --git a/test/modules/arch/linux/env.py b/test/modules/arch/linux/env.py index 0e3b4f6dd9d..7caf74fe996 100644 --- a/test/modules/arch/linux/env.py +++ b/test/modules/arch/linux/env.py @@ -211,6 +211,28 @@ def statuses(self) -> List[str]: NO_MONITOR_TIMEOUT = 15.0 +# The keep-alive notification is sent from the same monitor hook, so waiting +# for one costs the same as waiting for a status report. +WATCHDOG_TIMEOUT = MONITOR_TIMEOUT + +# The shortest WatchdogSec mod_systemd will accept without complaining, which +# is twice the monitor interval: the recommended keep-alive period is half the +# watchdog timeout, and half of anything shorter than this is out of reach of a +# hook which runs every ten seconds. Keep in step with mod_systemd.c. +SYSTEMD_MONITOR_INTERVAL = 10 +MIN_WATCHDOG_SEC = 2 * SYSTEMD_MONITOR_INTERVAL + + +def is_watchdog_ping(msg: Dict[str, str]) -> bool: + """Whether a notification carries the keep-alive ping. + + mod_systemd is free to send WATCHDOG=1 in a datagram of its own or + alongside whatever else it is reporting, so match on the assignment + rather than on the message being only that. + """ + return msg.get('WATCHDOG') == '1' + + # A configuration for a server run directly rather than through apachectl, # sharing the server root, module list and error log with the rest of the # suite but with its own pid file and port. @@ -435,12 +457,15 @@ class TransientService: """ def __init__(self, env: SystemdTestEnv, port: int, - name: str = None, extra: str = ''): + name: str = None, extra: str = '', + properties: List[str] = None): self.env = env self.port = port self.unit = name or f'httpd-test-{os.getpid()}' self.conf_file = write_server_conf(env, 'transient', port, extra=extra) self.pid_file = os.path.join(env.server_logs_dir, 'transient.pid') + # Extra --property arguments for the unit, such as WatchdogSec=. + self.properties = list(properties or []) def read_pid(self) -> Optional[int]: try: @@ -482,6 +507,7 @@ def start(self, timeout: float = 20.0) -> subprocess.CompletedProcess: '--property=KillMode=mixed', f'--property=ExecReload={httpd} -d {self.env.server_dir} ' f'-f {self.conf_file} -k graceful', + *[f'--property={p}' for p in self.properties], httpd, '-DFOREGROUND', '-d', self.env.server_dir, '-f', self.conf_file, ], capture_output=True, text=True, timeout=timeout) @@ -504,3 +530,43 @@ def __enter__(self) -> 'TransientService': def __exit__(self, *args): self.stop() + + +class ForegroundServer(ActivatedServer): + """httpd run directly in the foreground, with extra environment. + + The watchdog protocol is keyed to a process id: sd_watchdog_enabled(3) + ignores $WATCHDOG_USEC unless $WATCHDOG_PID is unset or names the + process reading it. apachectl cannot be used to set that, since the + variable has to name the parent httpd and the pid is not known until it + exists, so the value is assigned in a shell which then exec's httpd in + its own place -- the same trick ActivatedServer uses for $LISTEN_PID. + + Assignments are shell words, so "$$" in a value is the pid httpd will + have. + """ + + def __init__(self, env: SystemdTestEnv, port: int, + name: str = 'foreground', extra: str = '', + setenv: Dict[str, str] = None, + modules_conf: str = 'modules.conf'): + super().__init__(env, port, name=name, extra=extra, + modules_conf=modules_conf) + self.setenv = dict(setenv or {}) + + def args(self, fd: int = None) -> List[str]: + assigns = ' '.join(f'{k}={v}' for k, v in self.setenv.items()) + return [ + 'bash', '-c', + f'export {assigns}; exec "$0" "$@"' if assigns else 'exec "$0" "$@"', + self.env.httpd_bin, '-DFOREGROUND', + '-d', self.env.server_dir, '-f', self.conf_file, + ] + + def start(self) -> 'ForegroundServer': + # A new session, so the whole group can be signalled on the way out + # even when a failed restart leaves children behind. + self.proc = subprocess.Popen( + self.args(), env=self.env.server_env(), start_new_session=True, + stdout=subprocess.PIPE, stderr=subprocess.PIPE) + return self diff --git a/test/modules/arch/linux/test_001_notify.py b/test/modules/arch/linux/test_001_notify.py index 76b999fcf26..d79980bc0ac 100644 --- a/test/modules/arch/linux/test_001_notify.py +++ b/test/modules/arch/linux/test_001_notify.py @@ -127,16 +127,26 @@ def test_systemd_001_08_reloading_monotonic(self, env): assert 0 < int(msg['MONOTONIC_USEC']) <= time.clock_gettime_ns( time.CLOCK_MONOTONIC) // 1000 - @pytest.mark.xfail(reason="mod_systemd implements no watchdog keepalive, " - "so a unit using WatchdogSec= would be killed") def test_systemd_001_09_watchdog(self, env): + """A server started with $WATCHDOG_USEC reports that it is alive. + + $WATCHDOG_PID is left unset, which sd_watchdog_enabled(3) takes to + mean any process may report: it has to be, since apachectl starts a + parent whose pid nothing knew in advance. The keep-alive arrives + with the startup notifications rather than only from the monitor + hook ten seconds later, which is what makes this cheap to check. + test_006_watchdog.py covers the rest of the protocol. + """ assert env.apache_stop() == 0 - env.set_httpd_env('WATCHDOG_USEC', '2000000') # ping every 1s + # Long enough that mod_systemd does not object to it (AH10622). + env.set_httpd_env('WATCHDOG_USEC', str(60 * 1000000)) try: env.notify.clear() assert env.apache_restart() == 0 - assert env.notify.wait_for_key('WATCHDOG', timeout=4), \ - "no watchdog keepalive was sent" + msg = env.notify.wait_for_key('WATCHDOG', timeout=4) + assert msg, f"no watchdog keepalive was sent, " \ + f"got {env.notify.messages}" + assert msg['WATCHDOG'] == '1' finally: env.set_httpd_env('WATCHDOG_USEC', None) assert env.apache_restart() == 0 diff --git a/test/modules/arch/linux/test_006_watchdog.py b/test/modules/arch/linux/test_006_watchdog.py new file mode 100644 index 00000000000..d4fa8653bf6 --- /dev/null +++ b/test/modules/arch/linux/test_006_watchdog.py @@ -0,0 +1,211 @@ +import os +import re +import time + +import pytest + +from .env import (ForegroundServer, TransientService, MIN_WATCHDOG_SEC, + NO_MONITOR_TIMEOUT, WATCHDOG_TIMEOUT, is_watchdog_ping) + + +def watchdog_env(usec: int, pid: str = '$$') -> dict: + """The environment a service manager sets for a watched service. + + $WATCHDOG_PID names the process expected to report; "$$" is the shell + which exec's httpd, so it is the pid httpd will run as. + """ + env = {'WATCHDOG_USEC': str(usec)} + if pid is not None: + env['WATCHDOG_PID'] = pid + return env + + +class TestSystemdWatchdog: + """The keep-alive ping of the systemd watchdog protocol. + + A service whose unit sets WatchdogSec= is started with $WATCHDOG_USEC + holding that timeout in microseconds, and $WATCHDOG_PID holding the pid + expected to report. The service must then send "WATCHDOG=1" to the + notification socket more often than the timeout, or systemd puts the + unit into a failed state with Result=watchdog. The timeout is armed + once start-up completes and, as test_006_06 relies on, stays armed + across a reload. + + Nothing here needs systemd: the ping goes to $NOTIFY_SOCKET like every + other notification, so the same stand-in socket observes it. Only the + last test involves a service manager. + """ + + @pytest.fixture(autouse=True, scope='class') + def _class_scope(self, env): + # These run their own servers on the second port; the shared one + # would only add its notifications to the same socket. + assert env.apache_stop() == 0 + yield + assert env.apache_stop() == 0 + + @pytest.fixture + def server_factory(self, env): + started = [] + + def make(usec=None, pid='$$', extra='', name='watchdog'): + setenv = watchdog_env(usec, pid) if usec is not None else {} + srv = ForegroundServer(env, port=env.http_port2, name=name, + extra=extra, setenv=setenv) + started.append(srv) + env.notify.clear() + srv.start() + assert srv.is_live(), \ + f"server did not come up: {srv.stderr!r}" + return srv + + yield make + for srv in started: + srv.stop() + + def test_systemd_006_01_no_ping_when_unwatched(self, env, server_factory): + """A server the service manager is not watching sends no keep-alive. + + The monitor hook still runs -- its status report is the evidence of + that -- so the absence of a ping is a decision and not silence. + """ + server_factory() + assert env.notify.wait_for_status(r'^Total requests: ', + timeout=WATCHDOG_TIMEOUT), \ + "the monitor hook never ran, so this proves nothing" + assert not [m for m in env.notify.messages if is_watchdog_ping(m)], \ + "a keep-alive was sent with $WATCHDOG_USEC unset" + + def test_systemd_006_02_ping_when_watched(self, env, server_factory): + """With the watchdog enabled the keep-alive is sent.""" + server_factory(usec=60 * 1000000) + assert env.notify.wait_for(is_watchdog_ping, + timeout=WATCHDOG_TIMEOUT), \ + f"no keep-alive within {WATCHDOG_TIMEOUT}s, " \ + f"got {env.notify.messages}" + + def test_systemd_006_03_ping_repeats(self, env, server_factory): + """The keep-alive is periodic, which is the whole point of it: one + ping would satisfy a test but not systemd.""" + server_factory(usec=60 * 1000000) + for n in range(2): + assert env.notify.wait_for(is_watchdog_ping, + timeout=WATCHDOG_TIMEOUT), \ + f"only {n} keep-alives arrived, got {env.notify.messages}" + env.notify.clear() + + def test_systemd_006_04_ping_without_extended_status(self, env, + server_factory): + """The keep-alive does not depend on ExtendedStatus. + + The monitor hook declines early when it has no request counts to + report (test_003_03), and a server whose status line is switched + off must still be reported as alive. + """ + server_factory(usec=60 * 1000000, extra='ExtendedStatus off') + assert env.notify.wait_for_status(r'^Total requests: ', + timeout=NO_MONITOR_TIMEOUT) is None, \ + "ExtendedStatus off did not stop the status report" + assert env.notify.wait_for(is_watchdog_ping, + timeout=WATCHDOG_TIMEOUT), \ + "no keep-alive with ExtendedStatus off" + + def test_systemd_006_05_no_ping_for_another_pid(self, env, server_factory): + """$WATCHDOG_PID naming a different process means the variables were + set for something further up the process tree, and must be ignored. + """ + server_factory(usec=60 * 1000000, pid='1') + assert env.notify.wait_for_status(r'^Total requests: ', + timeout=WATCHDOG_TIMEOUT), \ + "the monitor hook never ran, so this proves nothing" + assert not [m for m in env.notify.messages if is_watchdog_ping(m)], \ + "a keep-alive was sent although $WATCHDOG_PID was another process" + + def test_systemd_006_06_ping_across_reload(self, env, server_factory): + """The keep-alive survives a graceful restart. + + The parent re-reads its configuration in the same process, but + mod_systemd is unloaded and loaded again with it, so anything it + remembered about the watchdog is gone by the time the monitor hook + runs again. systemd keeps the timeout armed throughout. + """ + srv = server_factory(usec=60 * 1000000) + assert env.notify.wait_for(is_watchdog_ping, timeout=WATCHDOG_TIMEOUT) + env.notify.clear() + assert srv.reload() == 0 + assert srv.is_live() + assert env.notify.wait_for(is_watchdog_ping, + timeout=WATCHDOG_TIMEOUT), \ + f"no keep-alive after a reload, got {env.notify.messages}" + + def test_systemd_006_07_ping_covers_the_reload_window(self, env, + server_factory): + """A keep-alive is sent as the configuration is read, and again once + it is loaded. + + Reading the configuration happens outside the parent's monitor loop, + so nothing else reports during it. The watchdog stays armed while + the unit reloads, and a configuration which takes longer to parse + than the timeout would otherwise be killed halfway through. + """ + srv = server_factory(usec=60 * 1000000) + assert env.notify.wait_for(is_watchdog_ping, timeout=WATCHDOG_TIMEOUT) + env.notify.clear() + assert srv.reload() == 0 + assert env.notify.wait_for( + lambda m: 'RELOADING' in m and is_watchdog_ping(m), + timeout=WATCHDOG_TIMEOUT), \ + f"no keep-alive as the configuration was read, " \ + f"got {env.notify.messages}" + assert env.notify.wait_for( + lambda m: m.get('READY') == '1' and is_watchdog_ping(m), + timeout=WATCHDOG_TIMEOUT), \ + f"no keep-alive once the configuration was loaded, " \ + f"got {env.notify.messages}" + + def test_systemd_006_08_short_timeout_warned(self, env, server_factory): + """A WatchdogSec the parent cannot meet is reported. + + The keep-alive is sent from the monitor hook, which runs once every + ten turns of the parent's one second loop. A timeout of a few + seconds cannot be met however the module is written, and failing + silently would leave the server being killed and restarted with + nothing in the log to say why. + """ + server_factory(usec=2 * 1000000) + assert env.httpd_error_log.scan_recent( + re.compile(r'.*AH10621: .*[Ww]atchdog.*'), timeout=10), \ + "no warning about a watchdog timeout that cannot be met" + env.httpd_error_log.ignore_recent(lognos=['AH10621']) + + def test_systemd_006_09_workable_timeout_not_warned(self, env, + server_factory): + """A timeout the parent can meet is not complained about.""" + server_factory(usec=MIN_WATCHDOG_SEC * 1000000) + assert env.notify.wait_for(is_watchdog_ping, timeout=WATCHDOG_TIMEOUT) + with pytest.raises(TimeoutError): + env.httpd_error_log.scan_recent( + re.compile(r'.*AH10621: .*'), timeout=1) + + @pytest.mark.skipif(not TransientService.is_available(), + reason="no per-user systemd manager") + def test_systemd_006_10_service_keeps_watchdog_alive(self, env): + """The real thing: systemd records each keep-alive it receives, and + the unit stays active rather than failing with Result=watchdog.""" + with TransientService(env, port=env.http_port2, + properties=[f'WatchdogSec={MIN_WATCHDOG_SEC}s'], + name=f'httpd-wd-{os.getpid()}') as svc: + assert svc.start().returncode == 0 + assert svc.wait_active() + first = svc.show('WatchdogTimestampMonotonic') + assert first and int(first) > 0, \ + "systemd recorded no keep-alive at all" + end = time.time() + WATCHDOG_TIMEOUT + while time.time() < end: + if svc.show('WatchdogTimestampMonotonic') != first: + break + time.sleep(0.5) + assert svc.show('WatchdogTimestampMonotonic') != first, \ + "systemd received no further keep-alive" + assert svc.show('ActiveState') == 'active' + assert svc.show('Result') == 'success'