From 4ded8ecee48195e2166492b0b56b955915ce7c71 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Thu, 15 Oct 2026 16:11:27 -0400 Subject: [PATCH] fix(mcp): get_anomaly shows a quick Steward restart, not only a gap over 90 s (#5862) A redeploy's new process ticks at once, so its once-a-minute samples never broke for 90 s and get_anomaly showed none of the day's restarts. The first self-monitor tick in a process now records restart_gap_secs (time since the last process's last sample), and steward_gaps shows each one as a restart. Co-Authored-By: Claude Opus 5.5 --- docs/core/alerting.md | 1 + docs/plugins/writing-a-plugin.md | 2 +- steward/alerts/service.py | 2 +- steward/core/formatting.py | 1 + steward/core/self_monitor.py | 9 ++++++++- steward/mcp/tools/_events.py | 27 +++++++++++++++++++-------- tests/core/test_self_monitor.py | 22 ++++++++++++++++++++++ tests/mcp/test_anomaly_review.py | 15 +++++++++++++++ 8 files changed, 68 insertions(+), 11 deletions(-) diff --git a/docs/core/alerting.md b/docs/core/alerting.md index 8efac52..77b5790 100644 --- a/docs/core/alerting.md +++ b/docs/core/alerting.md @@ -138,6 +138,7 @@ failed agent posts, a gap in watching, or open files near the limit. | `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 | +| `restart_gap_secs` | Recorded once, on a new process's first tick: the time since the last process's last sample, however short | | `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`) | diff --git a/docs/plugins/writing-a-plugin.md b/docs/plugins/writing-a-plugin.md index a0c0499..7f4c86d 100644 --- a/docs/plugins/writing-a-plugin.md +++ b/docs/plugins/writing-a-plugin.md @@ -408,7 +408,7 @@ async def mcp_events(db, host_id, host_name, since, until) -> list[dict]: A resource with no host (a Traefik router, say) has no host to read events by. A plugin that knows what happened to one of its own resources exports `mcp_resource_events(db, source, resource, since, until)` instead, same return shape, and returns `[]` for a source that isn't its own. Traefik's is the example: it gives a router's swarm service's container events, on whichever hosts they ran. -Core adds, beside every anomaly, the stretches Steward itself wasn't recording (kind `"steward"`: a restart, a deploy, a stall), read from its own once-a-minute health sample. A plugin doesn't need to report those. +Core adds, beside every anomaly, the stretches Steward itself wasn't recording (kind `"steward"`: a restart, a deploy, a stall), read from its own once-a-minute health sample; a restart is shown however quick, from the `restart_gap_secs` its new process records. A plugin doesn't need to report those. --- diff --git a/steward/alerts/service.py b/steward/alerts/service.py index 33f476d..158c1db 100644 --- a/steward/alerts/service.py +++ b/steward/alerts/service.py @@ -28,7 +28,7 @@ CORE_METRICS: dict[str, list[str]] = { "dns": ["is_up", "response_ms"], "http": ["is_up", "response_ms"], "steward": ["ingest_posts", "ingest_failed", "ingest_slowest_ms", "db_roundtrip_ms", - "unwatched_secs", "cleanup_secs", "open_fds", "open_fds_pct", + "unwatched_secs", "restart_gap_secs", "cleanup_secs", "open_fds", "open_fds_pct", "backup_age_secs", "backup_bytes"], } diff --git a/steward/core/formatting.py b/steward/core/formatting.py index b26ab98..4acf17f 100644 --- a/steward/core/formatting.py +++ b/steward/core/formatting.py @@ -298,6 +298,7 @@ METRICS: dict[str, tuple[str, str]] = { "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"), + "restart_gap_secs": ("Restarted after", "recorded when Steward starts: how long since it last recorded"), "cleanup_secs": ("Hourly cleanup took", "how long the last retention and rollup run took"), "backup_age_secs": ("Newest backup's age", "time since Steward last sent a backup to its bucket"), "backup_bytes": ("Backup size", "the size of the last backup sent"), diff --git a/steward/core/self_monitor.py b/steward/core/self_monitor.py index 7170ff0..6163ca2 100644 --- a/steward/core/self_monitor.py +++ b/steward/core/self_monitor.py @@ -25,6 +25,10 @@ source and resource: • ``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 + • ``restart_gap_secs`` — once, on a fresh process's first tick: how long since + the last process's last sample, however short. A quick redeploy never + breaks the minute long enough to show as unwatched; this marks it anyway, + so get_anomaly can show Steward's own restarts beside an anomaly (#5862) ``cleanup_secs`` is recorded by the hourly cleanup itself when it finishes. """ @@ -51,6 +55,7 @@ except ImportError: # pragma: no cover - non-POSIX FD_WARN_PCT = 80.0 _warned = False # de-dupe the WARNING so a sustained leak doesn't spam the log +_started = False # this process has ticked: restart_gap_secs is recorded on the first tick only def count_open_fds() -> int | None: @@ -98,7 +103,7 @@ async def record_self_metrics(app) -> None: The open-file pair is skipped (logged at debug) where fd accounting isn't available, so it's safe to schedule unconditionally. """ - global _warned + global _warned, _started from sqlalchemy import select, text from steward.models.metrics import PluginMetricLatest @@ -129,11 +134,13 @@ async def record_self_metrics(app) -> None: ("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)), + ("restart_gap_secs", None if _started or last is None else (now - last).total_seconds()), ("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) + _started = True if pct is not None and pct >= FD_WARN_PCT: if not _warned: diff --git a/steward/mcp/tools/_events.py b/steward/mcp/tools/_events.py index b5827dc..33edcf5 100644 --- a/steward/mcp/tools/_events.py +++ b/steward/mcp/tools/_events.py @@ -152,13 +152,23 @@ async def other_anomalies(db, place: Place, anomaly_id: str, since: datetime, return here, elsewhere -def gaps_in(times: list[datetime], since: datetime, until: datetime) -> list[dict]: - """Each break longer than STEWARD_GAP_S between consecutive samples that - overlaps the window, as a "steward" event lasting the break.""" +def gaps_in(times: list[datetime], since: datetime, until: datetime, + restarts: list[tuple[datetime, float]] = ()) -> list[dict]: + """Each restart (its first sample's time and how long since the last + one) and each other break longer than STEWARD_GAP_S between consecutive + samples that overlaps the window, as a "steward" event lasting the break. + A restart is shown however short: a quick redeploy never breaks the + minute, and still restarts every count Steward keeps.""" out = [] + for at, secs in restarts: + if at >= since and at - timedelta(seconds=secs) <= until: + out.append(event(at - timedelta(seconds=secs), "steward", + f"Steward restarted, not recording for {human_duration(secs)}: " + "readings either side of it can be wrong", until=at)) + restarted = {at for at, _ in restarts} for before, after in zip(times, times[1:]): secs = (after - before).total_seconds() - if secs > STEWARD_GAP_S and after >= since and before <= until: + if secs > STEWARD_GAP_S and after >= since and before <= until and after not in restarted: out.append(event(before, "steward", f"Steward wasn't recording for {human_duration(secs)} (a restart, a deploy or a " "stall): readings either side of a gap can be wrong", until=after)) @@ -172,12 +182,13 @@ async def steward_gaps(db, since: datetime, until: datetime) -> list[dict]: silence (#5862). Raw samples only, so a window older than their retention shows none.""" rows = (await db.execute( - select(PluginMetric.recorded_at).where( + select(PluginMetric.metric_name, PluginMetric.recorded_at, PluginMetric.value).where( PluginMetric.source_module == "steward", PluginMetric.resource_name == "process", - PluginMetric.metric_name == "db_roundtrip_ms", + PluginMetric.metric_name.in_(("db_roundtrip_ms", "restart_gap_secs")), PluginMetric.recorded_at >= since - timedelta(hours=1), PluginMetric.recorded_at <= until) - .order_by(PluginMetric.recorded_at))).scalars() - return gaps_in(list(rows), since, until) + .order_by(PluginMetric.recorded_at))).all() + return gaps_in([at for name, at, _ in rows if name == "db_roundtrip_ms"], since, until, + [(at, value) for name, at, value in rows if name == "restart_gap_secs"]) async def plugin_events(place: Place, since: datetime, until: datetime) -> list[list[dict]]: diff --git a/tests/core/test_self_monitor.py b/tests/core/test_self_monitor.py index 32e1ee5..0485b26 100644 --- a/tests/core/test_self_monitor.py +++ b/tests/core/test_self_monitor.py @@ -144,3 +144,25 @@ def test_unwatched_counts_only_a_real_gap(): 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 + + +def test_a_fresh_process_marks_its_restart_once(monkeypatch): + """#5862: the first tick records how long since the last process's last + sample, however short; later ticks and a first-ever start don't.""" + from datetime import datetime, timedelta, timezone + recorded = _patch_recorder(monkeypatch) + monkeypatch.setattr(sm, "_started", False) + monkeypatch.setattr(_FakeSession, "last", datetime.now(timezone.utc) - timedelta(seconds=40)) + + asyncio.run(sm.record_self_metrics(_FakeApp())) + asyncio.run(sm.record_self_metrics(_FakeApp())) + + gaps = [v for (_s, _r, m, v) in recorded if m == "restart_gap_secs"] + assert len(gaps) == 1 and 39 <= gaps[0] <= 60 + assert dict((m, v) for (_s, _r, m, v) in recorded)["unwatched_secs"] == 0.0 + + recorded.clear() + monkeypatch.setattr(sm, "_started", False) + monkeypatch.setattr(_FakeSession, "last", None) + asyncio.run(sm.record_self_metrics(_FakeApp())) + assert "restart_gap_secs" not in {m for (_s, _r, m, _v) in recorded} diff --git a/tests/mcp/test_anomaly_review.py b/tests/mcp/test_anomaly_review.py index 8858274..21d20d8 100644 --- a/tests/mcp/test_anomaly_review.py +++ b/tests/mcp/test_anomaly_review.py @@ -137,3 +137,18 @@ def test_steward_not_recording_is_an_event_beside_every_anomaly(): assert gap["until"] == "2026-10-15T12:04:10Z" and "wasn't recording" in gap["what"] assert _events.gaps_in(ticks, NOW + timedelta(minutes=5), NOW + timedelta(hours=1)) == [] assert _events.gaps_in([NOW + timedelta(minutes=m) for m in range(5)], NOW, NOW + timedelta(hours=1)) == [] + + +def test_a_quick_restart_is_shown_though_it_never_broke_the_minute(): + """A redeploy's new process ticks at once, so the samples stay under a + minute apart; its first tick's restart_gap_secs marks it (#5862).""" + ticks = [NOW, NOW + timedelta(seconds=60), NOW + timedelta(seconds=95), NOW + timedelta(seconds=155)] + restart = NOW + timedelta(seconds=95) + [ev] = _events.gaps_in(ticks, NOW, NOW + timedelta(hours=1), [(restart, 35.0)]) + assert ev["kind"] == "steward" and "restarted" in ev["what"] + assert (ev["at"], ev["until"]) == ("2026-10-15T12:01:00Z", "2026-10-15T12:01:35Z") + # A long restart is one event, not a restart and a gap. + slow = NOW + timedelta(minutes=5) + [ev] = _events.gaps_in([NOW, slow], NOW, NOW + timedelta(hours=1), [(slow, 300.0)]) + assert "restarted" in ev["what"] + assert _events.gaps_in(ticks, NOW + timedelta(minutes=2), NOW + timedelta(hours=1), [(restart, 35.0)]) == []