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 <noreply@anthropic.com>
This commit is contained in:
@@ -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`) |
|
||||
|
||||
|
||||
@@ -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.
|
||||
|
||||
---
|
||||
|
||||
|
||||
@@ -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"],
|
||||
}
|
||||
|
||||
|
||||
@@ -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"),
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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]]:
|
||||
|
||||
@@ -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}
|
||||
|
||||
@@ -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)]) == []
|
||||
|
||||
Reference in New Issue
Block a user