diff --git a/docs/core/alerting.md b/docs/core/alerting.md index 7a2a495..cd49490 100644 --- a/docs/core/alerting.md +++ b/docs/core/alerting.md @@ -123,6 +123,24 @@ each covering rule's `hosts` and each host's rule's `part_of`. | `traefik` | `latency_p95_ms` | Approximate p95 latency (ms) | | `traefik` | `latency_p99_ms` | Approximate p99 latency (ms) | +#### Steward itself + +Source `steward`, resource `process`, recorded once a minute by the +self-monitor tick (`steward/core/self_monitor.py`; the ingest tally is in +`steward/core/health.py`). Settings → System (`/settings/system/`, admin) +shows each one now and over the last day, with a verdict above that names +failed agent posts, a gap in watching, or open files near the limit. + +| `metric_name` | Description | +|---|---| +| `ingest_posts` | Host-agent posts Steward took in the last minute | +| `ingest_failed` | Posts in the last minute that didn't land (handler raised, or the agent gave up) | +| `ingest_slowest_ms` | The slowest post in the last minute; agents give up at 10 s | +| `db_roundtrip_ms` | A `SELECT 1`, connection checkout included | +| `unwatched_secs` | The gap before this tick when it exceeds `watch.GAP_S` (a deploy or an outage); 0 when unbroken | +| `cleanup_secs` | How long the last hourly retention and rollup run took | +| `open_fds` / `open_fds_pct` | Steward's open files, and as a share of its limit (absent without `/proc`) | + --- ## Notifications diff --git a/plugins/host_agent/routes.py b/plugins/host_agent/routes.py index 9aa4ff0..ee94985 100644 --- a/plugins/host_agent/routes.py +++ b/plugins/host_agent/routes.py @@ -17,6 +17,7 @@ from sqlalchemy import select, or_, and_ from datetime import timedelta from steward.core.formatting import worst_reading +from steward.core.health import ingest as ingest_tally from steward.core.metric_series import points as metric_points from steward.core.settings import get_setting, public_base_url from steward.core.time_range import parse_range, RANGE_OPTIONS @@ -368,7 +369,14 @@ async def ingest(): # The agent hung up (its 10 s timeout) and the server dropped the # request: say how far it got before re-raising. phases.cancelled(token_hash[:8]) + ingest_tally.done(phases.elapsed_ms(), ok=False) raise + except Exception: + ingest_tally.done(phases.elapsed_ms(), ok=False) + raise + # Counted for Steward's own health (#5467). The early returns above (a + # bad token, no valid samples) answer the agent and aren't counted. + ingest_tally.done(phases.elapsed_ms()) phases.report(host.name, accepted, len(metric_rows), sum(len(c) for _, c in docker_snapshots), @@ -410,6 +418,9 @@ class _Phases: self.took: dict[str, float] = {} self.size = "" + def elapsed_ms(self) -> float: + return (time.monotonic() - self.start) * 1000.0 + def mark(self, name: str) -> None: now = time.monotonic() self.took[name] = self.took.get(name, 0.0) + (now - self.last) diff --git a/steward/alerts/service.py b/steward/alerts/service.py index 433b804..aecb2b7 100644 --- a/steward/alerts/service.py +++ b/steward/alerts/service.py @@ -27,7 +27,8 @@ CORE_METRICS: dict[str, list[str]] = { "tcp": ["is_up", "response_ms"], "dns": ["is_up", "response_ms"], "http": ["is_up", "response_ms"], - "steward": ["open_fds", "open_fds_pct"], + "steward": ["ingest_posts", "ingest_failed", "ingest_slowest_ms", "db_roundtrip_ms", + "unwatched_secs", "cleanup_secs", "open_fds", "open_fds_pct"], } diff --git a/steward/app.py b/steward/app.py index 41e5b30..e36784c 100644 --- a/steward/app.py +++ b/steward/app.py @@ -414,8 +414,14 @@ def _register_core_tasks(app: Quart) -> None: await run_due_monitors(app) async def run_cleanup(): + import time from .core.cleanup import run_cleanup as _cleanup + from .core.self_monitor import record_cleanup_secs + started = time.monotonic() await _cleanup(app) + # How long it took, as Steward's own metric (#5467); a failed run + # raises past this and records nothing. + await record_cleanup_secs(app, time.monotonic() - started) async def run_alert_reconcile(): from .alerts.service import reconcile_covering_rules diff --git a/steward/core/formatting.py b/steward/core/formatting.py index 160aab8..1e54f6a 100644 --- a/steward/core/formatting.py +++ b/steward/core/formatting.py @@ -276,6 +276,12 @@ METRICS: dict[str, tuple[str, str]] = { "is_up": ("Up or down", "whether the check passed"), "is_healthy": ("Health check", "the container's own HEALTHCHECK result"), "response_ms": ("Response time", "how long the check took"), + "ingest_posts": ("Agent posts per minute", "host-agent reports Steward took in the last minute"), + "ingest_failed": ("Failed agent posts", "reports in the last minute that didn't land"), + "ingest_slowest_ms": ("Slowest agent post", "the longest report in the last minute; agents give up at 10 s"), + "db_roundtrip_ms": ("Database round trip", "a trivial query to Steward's database, connection included"), + "unwatched_secs": ("Time not watching", "how long Steward wasn't recording before this minute; 0 when unbroken"), + "cleanup_secs": ("Hourly cleanup took", "how long the last retention and rollup run took"), "open_fds": ("Open files", "files Steward itself has open"), "open_fds_pct": ("Open files (% of limit)", "files Steward has open, against its limit"), "request_rate": ("Requests per second", "requests through this router"), diff --git a/steward/core/health.py b/steward/core/health.py new file mode 100644 index 0000000..d5acc0b --- /dev/null +++ b/steward/core/health.py @@ -0,0 +1,69 @@ +"""Steward's own health between self-monitor ticks (#5467). + +The host-agent ingest reports each post here as it finishes; the self-monitor +tick (core/self_monitor.py) takes the minute's totals and records them as +metrics under source "steward", resource "process", beside the open-file +counts, where alert rules can watch them like any other metric. One process +serves Steward, so a module-level counter is the whole of it. +""" +from __future__ import annotations + +from dataclasses import dataclass + +# Steward's own metrics, in the order the Settings → System page lists them. +PROCESS_METRICS = ["ingest_posts", "ingest_failed", "ingest_slowest_ms", "db_roundtrip_ms", + "unwatched_secs", "cleanup_secs", "open_fds", "open_fds_pct"] + + +@dataclass +class IngestTally: + posts: int = 0 + failed: int = 0 + slowest_ms: float = 0.0 + + def done(self, ms: float, ok: bool = True) -> None: + """One ingest post finished in `ms`; `ok` False when it didn't land + (the agent gave up, or the handler raised).""" + self.posts += 1 + if not ok: + self.failed += 1 + self.slowest_ms = max(self.slowest_ms, ms) + + def take(self) -> "IngestTally": + """The totals since the last take, starting the next minute afresh.""" + got = IngestTally(self.posts, self.failed, self.slowest_ms) + self.posts, self.failed, self.slowest_ms = 0, 0, 0.0 + return got + + +ingest = IngestTally() + + +async def process_health(db) -> dict: + """What Settings → System shows (#5467): each of Steward's own metrics now + and over the last day, and the problems among them, worst first. + + Returns {"rows": [{metric, now, at, low, high, series}], "problems": [str], + "seen": bool}. Reads plugin_metric_latest and a day of each series (the + covering series index makes that cheap, #5490).""" + from steward.alerts.service import metric_preview + from steward.core.formatting import human_duration + rows = [] + for metric in PROCESS_METRICS: + p = await metric_preview(db, "steward", "process", metric) + rows.append({"metric": metric, **(p or {"now": None, "at": None, "series": [], + "low": None, "high": None})}) + by = {r["metric"]: r for r in rows} + problems = [] + if (by["ingest_failed"]["now"] or 0) > 0: + problems.append(f"{by['ingest_failed']['now']:.0f} agent posts failed in the last minute") + elif (by["ingest_failed"]["high"] or 0) > 0: + problems.append(f"agent posts failed in the last day, up to {by['ingest_failed']['high']:.0f} " + "in a minute") + if (by["unwatched_secs"]["high"] or 0) > 0: + problems.append(f"Steward wasn't watching for up to {human_duration(by['unwatched_secs']['high'])} " + "in the last day (a deploy or an outage)") + from steward.core.self_monitor import FD_WARN_PCT + if (by["open_fds_pct"]["now"] or 0) >= FD_WARN_PCT: + problems.append(f"open files at {by['open_fds_pct']['now']:.0f}% of the limit") + return {"rows": rows, "problems": problems, "seen": any(r["at"] for r in rows)} diff --git a/steward/core/self_monitor.py b/steward/core/self_monitor.py index 2f76487..7170ff0 100644 --- a/steward/core/self_monitor.py +++ b/steward/core/self_monitor.py @@ -1,4 +1,4 @@ -"""Self-monitoring: record Steward's own open file-descriptor usage. +"""Self-monitoring: record Steward's own health each minute. A leaked socket/file handle in a poll loop (see the SNMP and UniFi fd-leak issues) used to fail silently until the process hit its fd ceiling and @@ -16,10 +16,25 @@ Both flow through the normal alert pipeline, so the operator can attach an alert rule to either via the existing alert-rules UI. As a zero-config floor we also log a WARNING once usage crosses ``FD_WARN_PCT`` — a leak becomes visible even before any rule is set up. + +The same tick records the rest of Steward's health (#5467), under the same +source and resource: + + • ``ingest_posts`` / ``ingest_failed`` / ``ingest_slowest_ms`` — the host-agent + posts since the last tick (core/health.py), how many didn't land, the slowest + • ``db_roundtrip_ms`` — a timed ``SELECT 1``, connection checkout included + • ``unwatched_secs`` — how long Steward wasn't recording before this tick (a + deploy, an outage, a stalled loop), from its own last sample; 0 when unbroken + +``cleanup_secs`` is recorded by the hourly cleanup itself when it finishes. """ from __future__ import annotations import logging import os +import time +from datetime import datetime, timezone + +from sqlalchemy import func logger = logging.getLogger(__name__) @@ -67,40 +82,57 @@ def fd_soft_limit() -> int | None: return soft -async def record_self_metrics(app) -> None: - """Record open-fd usage as Steward's own metrics; warn past the floor. +def unwatched_secs(last: datetime | None, now: datetime) -> float: + """How long Steward wasn't recording before `now`, given its last sample: + 0 when the ticks are unbroken (a gap no longer than core.watch.GAP_S).""" + from .watch import GAP_S + if last is None: + return 0.0 + gap = (now - last).total_seconds() + return gap if gap > GAP_S else 0.0 - No-op (logged at debug) when fd accounting isn't available on this platform, - so it's safe to schedule unconditionally. + +async def record_self_metrics(app) -> None: + """Record Steward's own health as metrics; warn past the open-file floor. + + The open-file pair is skipped (logged at debug) where fd accounting isn't + available, so it's safe to schedule unconditionally. """ global _warned + from sqlalchemy import select, text + from steward.models.metrics import PluginMetricLatest + from .alerts import MetricBatch + from .health import ingest + fds = count_open_fds() if fds is None: logger.debug("self_monitor: /proc/self/fd unavailable — skipping fd metrics") - return - - from .alerts import MetricBatch - soft = fd_soft_limit() - pct = (fds / soft * 100.0) if soft else None + pct = (fds / soft * 100.0) if (fds is not None and soft) else None + tally = ingest.take() + now = datetime.now(timezone.utc) + started = time.monotonic() async with app.db_sessionmaker() as session: async with session.begin(): + await session.execute(text("SELECT 1")) + roundtrip_ms = (time.monotonic() - started) * 1000.0 + # The last tick's sample, whatever restarts came between. + last = (await session.execute(select(func.max(PluginMetricLatest.recorded_at)).where( + PluginMetricLatest.source_module == "steward", + PluginMetricLatest.resource_name == "process", + PluginMetricLatest.metric_name == "db_roundtrip_ms"))).scalar() batch = MetricBatch() - batch.add( - source_module="steward", - resource_name="process", - metric_name="open_fds", - value=float(fds), - ) - if pct is not None: - batch.add( - source_module="steward", - resource_name="process", - metric_name="open_fds_pct", - value=pct, - ) + # Literal names, so tests/core/test_metric_catalog.py sees each one. + for metric_name, value in [ + ("ingest_posts", tally.posts), ("ingest_failed", tally.failed), + ("ingest_slowest_ms", tally.slowest_ms), ("db_roundtrip_ms", roundtrip_ms), + ("unwatched_secs", unwatched_secs(last, now)), + ("open_fds", fds), ("open_fds_pct", pct)]: + if value is not None: + batch.add(source_module="steward", resource_name="process", + metric_name=metric_name, value=value, recorded_at=now) await batch.record(session) if pct is not None and pct >= FD_WARN_PCT: @@ -113,4 +145,16 @@ async def record_self_metrics(app) -> None: else: _warned = False # recovered — re-arm the warning for the next breach - logger.debug("self_monitor: open_fds=%d soft_limit=%s pct=%s", fds, soft, pct) + logger.debug("self_monitor: open_fds=%s soft_limit=%s pct=%s ingest=%s db=%.0fms", + fds, soft, pct, tally, roundtrip_ms) + + +async def record_cleanup_secs(app, secs: float) -> None: + """How long the hourly cleanup just took (#5467), as Steward's own metric.""" + from .alerts import MetricBatch + async with app.db_sessionmaker() as session: + async with session.begin(): + batch = MetricBatch() + batch.add(source_module="steward", resource_name="process", + metric_name="cleanup_secs", value=secs) + await batch.record(session) diff --git a/steward/settings/routes.py b/steward/settings/routes.py index c905c68..e2f5d09 100644 --- a/steward/settings/routes.py +++ b/steward/settings/routes.py @@ -623,6 +623,22 @@ async def _reports_page(settings: dict, flash): shown_day=shown_day, shown_hour=shown_hour, last_sent=last_sent) +@settings_bp.get("/system/") +@require_role(UserRole.admin) +async def system(): + """Steward's own health (#5467): its process metrics now and over the day, + each one an alert rule can watch (source "Steward itself").""" + from steward.core.health import process_health + from steward.core.status import sparkline_svg + async with current_app.db_sessionmaker() as db: + health = await process_health(db) + for row in health["rows"]: + # From zero to the row's own peak, with a floor (UI & Design ruling 8). + row["spark"] = sparkline_svg(row["series"], width=120, height=20, + stroke="currentColor", floor=1.0) if len(row["series"]) > 1 else "" + return await render_template("settings/system.html", **health) + + @settings_bp.get("/reports/") @require_role(UserRole.admin) async def reports(): diff --git a/steward/templates/settings/_tabs.html b/steward/templates/settings/_tabs.html index f12a57b..e2e2434 100644 --- a/steward/templates/settings/_tabs.html +++ b/steward/templates/settings/_tabs.html @@ -10,5 +10,6 @@ ("auth", "Authentication", "/settings/auth/"), ("users", "Users", "/settings/users/"), ("ansible", "Ansible", "/settings/ansible/"), - ("plugins", "Plugins", "/settings/plugins/")], active, "Settings") }} + ("plugins", "Plugins", "/settings/plugins/"), + ("system", "System", "/settings/system/")], active, "Settings") }} {%- endmacro %} diff --git a/steward/templates/settings/system.html b/steward/templates/settings/system.html new file mode 100644 index 0000000..92e7221 --- /dev/null +++ b/steward/templates/settings/system.html @@ -0,0 +1,41 @@ +{# settings/system.html — Steward's own health (#5467): a verdict, then each of + its process metrics now and over the last day, from the self-monitor tick. + Each is a metric an alert rule can watch under "Steward itself". #} +{% extends "base.html" %} +{% from "_macros.html" import crumbs %} +{% from "settings/_tabs.html" import settings_tabs %} +{% block title %}Settings — System — Steward{% endblock %} +{% block section_tabs %}{{ settings_tabs("system") }}{% endblock %} +{% block breadcrumb %}{{ crumbs([("Settings", "/settings/"), ("System", "")]) }}{% endblock %} +{% block content %} +

+ {%- if not seen %}No readings yet: the first arrive within a minute of Steward starting. + {%- elif problems %}{% set said = problems|join("; ") %}{{ said[:1]|upper }}{{ said[1:] }}. + {%- else %}Steward is running normally.{% endif -%} +

+ +

Steward itself

+
+ + + + {% for r in rows %} + + + + + + {% endfor %} + +
MeasureNowLast 24 h
{{ metric_label(r.metric) }} +
{{ metric_about(r.metric) }}
{{ metric_value(r.metric, r.now) }} + {%- if r.at %}
{{ r.at|ago }}
{% endif %}
+ {%- if r.low is not none %}{{ metric_value(r.metric, r.low) }} – {{ metric_value(r.metric, r.high) }} + + {%- else %}—{% endif -%} +
+
+

+ Recorded each minute (the cleanup each hour). Any of these can be watched by an + alert rule: pick the source "Steward itself".

+{% endblock %} diff --git a/tests/core/test_self_monitor.py b/tests/core/test_self_monitor.py index cff4316..32e1ee5 100644 --- a/tests/core/test_self_monitor.py +++ b/tests/core/test_self_monitor.py @@ -1,4 +1,4 @@ -"""Unit tests for the self-fd watchdog (no DB, no network). +"""Unit tests for the self-monitor: open files and Steward's own health (no DB, no network). Exercises the fd accounting, the percentage/warning floor, and that the recorder degrades to a no-op where fd accounting isn't available. The DB session @@ -36,9 +36,15 @@ class _Ctx: class _FakeSession(_Ctx): + last = None # the latest steward sample the unwatched gap is counted from + def begin(self): return _Ctx() + async def execute(self, stmt): + last = self.last + return type("R", (), {"scalar": staticmethod(lambda: last)})() + class _FakeApp: def db_sessionmaker(self): @@ -104,12 +110,37 @@ def test_no_warning_below_floor(monkeypatch, caplog): assert not any("soft limit" in r.message for r in caplog.records) -def test_noop_when_fd_count_unavailable(monkeypatch): - # /proc absent → must return before touching the DB. +def test_without_fd_accounting_the_rest_is_still_recorded(monkeypatch): + # /proc absent: no open-file pair, but Steward's other health still lands. + recorded = _patch_recorder(monkeypatch) monkeypatch.setattr(sm, "count_open_fds", lambda: None) - class _Boom: - def db_sessionmaker(self): - raise AssertionError("must not open a session when fds are unknown") + asyncio.run(sm.record_self_metrics(_FakeApp())) - asyncio.run(sm.record_self_metrics(_Boom())) # no raise + names = {m for (_s, _r, m, _v) in recorded} + assert "db_roundtrip_ms" in names and not names & {"open_fds", "open_fds_pct"} + + +def test_the_minute_s_ingests_are_recorded_and_the_tally_starts_again(monkeypatch): + """#5467: posts, failures and the slowest post since the last tick.""" + from steward.core import health + recorded = _patch_recorder(monkeypatch) + monkeypatch.setattr(sm, "count_open_fds", lambda: 50) + monkeypatch.setattr(health, "ingest", health.IngestTally()) + for ms, ok in ((300.0, True), (9800.0, False), (450.0, True)): + health.ingest.done(ms, ok) + + asyncio.run(sm.record_self_metrics(_FakeApp())) + + got = {m: v for (s, r, m, v) in recorded if (s, r) == ("steward", "process")} + assert (got["ingest_posts"], got["ingest_failed"], got["ingest_slowest_ms"]) == (3.0, 1.0, 9800.0) + assert got["unwatched_secs"] == 0.0 and got["db_roundtrip_ms"] >= 0 + assert health.ingest.take() == health.IngestTally() # taken: the next minute starts at zero + + +def test_unwatched_counts_only_a_real_gap(): + from datetime import datetime, timedelta, timezone + now = datetime(2026, 10, 9, 12, 0, tzinfo=timezone.utc) + assert sm.unwatched_secs(None, now) == 0.0 # first ever tick + assert sm.unwatched_secs(now - timedelta(seconds=61), now) == 0.0 # an ordinary minute + assert sm.unwatched_secs(now - timedelta(minutes=7), now) == 420.0 # a deploy or outage diff --git a/tests/core/test_steward_health.py b/tests/core/test_steward_health.py new file mode 100644 index 0000000..c93d10b --- /dev/null +++ b/tests/core/test_steward_health.py @@ -0,0 +1,60 @@ +"""Settings → System (#5467): Steward's own health, a verdict then each measure +now and over the day. The verdict names what is wrong, and only that.""" +from datetime import datetime, timezone + +import pytest +from quart import render_template, session + +from steward.core import health + +AT = datetime(2026, 10, 9, 12, 0, tzinfo=timezone.utc) + + +def _previews(**over): + base = {m: {"now": 0.0, "at": AT, "series": [0.0, 0.0], "low": 0.0, "high": 0.0} + for m in health.PROCESS_METRICS} + base["db_roundtrip_ms"] = {"now": 4.0, "at": AT, "series": [3.0, 5.0], "low": 2.0, "high": 9.0} + for m, v in over.items(): + base[m] = {**base[m], **v} + return base + + +@pytest.fixture +def previews(monkeypatch): + def use(**over): + got = _previews(**over) + + async def fake(db, source, resource, metric, now=None): + assert (source, resource) == ("steward", "process") + return got[metric] + monkeypatch.setattr("steward.alerts.service.metric_preview", fake) + return use + + +async def test_a_healthy_steward_has_no_problems(previews): + previews() + got = await health.process_health(None) + assert got["seen"] and got["problems"] == [] + assert [r["metric"] for r in got["rows"]] == health.PROCESS_METRICS + + +async def test_failures_and_gaps_are_named(previews): + previews(ingest_failed={"now": 2.0, "high": 2.0}, unwatched_secs={"high": 420.0}, + open_fds_pct={"now": 85.0}) + problems = (await health.process_health(None))["problems"] + assert problems[0] == "2 agent posts failed in the last minute" + assert "wasn't watching for up to 7m" in problems[1] + assert problems[2] == "open files at 85% of the limit" + + +async def test_the_page_reads_as_a_verdict_then_each_measure(app, previews): + previews(unwatched_secs={"high": 420.0}) + got = await health.process_health(None) + for r in got["rows"]: + r["spark"] = "" + async with app.test_request_context("/settings/system/"): + session["user_role"] = "admin" + page = " ".join((await render_template("settings/system.html", **got)).split()) + assert 'Steward wasn\'t watching for up to 7m' in page + assert "Database round trip" in page and "4 ms" in page and "2 ms – 9 ms" in page + assert page.index("page-verdict") < page.index("Agent posts per minute")