From 7ce61a20992f7a309fb87c4a7b56967e4251ffb6 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Thu, 8 Oct 2026 08:26:10 -0400 Subject: [PATCH] fix(traefik): grade routers on their last 15 minutes; the Config tile reads Traefik's reload time (#5355) The operator: problem cards "can disappear so quickly". Each router was graded on its latest scrape, so a 4xx share near the 1% cutoff crossed it on one scrape and fell back on the next. recent_window reads every router's last 15 minutes in one query, the error shares weighted by traffic; grade_routers uses it on the page and the dashboard widget, and the why says "over the last 15 min". traefik_config_last_reload_success is the Unix time of the last good reload, not a 0/1 flag, so the tile said "Reload failed" on every scrape. traefik_005 stores it as config_last_reload_at, and the tile reads "Config reloaded 3m ago". The router index also carries the 4xx share. Co-Authored-By: Claude Opus 5.5 --- .../versions/traefik_005_reload_at.py | 41 ++++++++++ plugins/traefik/models.py | 4 +- plugins/traefik/routes.py | 82 +++++++++++++++---- plugins/traefik/scraper.py | 16 ++-- plugins/traefik/templates/traefik/rows.html | 5 +- tests/integration/test_traefik_latest.py | 31 +++++++ tests/plugins/traefik/test_traefik_page.py | 39 +++++++++ 7 files changed, 194 insertions(+), 24 deletions(-) create mode 100644 plugins/traefik/migrations/versions/traefik_005_reload_at.py diff --git a/plugins/traefik/migrations/versions/traefik_005_reload_at.py b/plugins/traefik/migrations/versions/traefik_005_reload_at.py new file mode 100644 index 0000000..d798e4a --- /dev/null +++ b/plugins/traefik/migrations/versions/traefik_005_reload_at.py @@ -0,0 +1,41 @@ +"""Traefik's last good config reload is a moment; routers are graded on a window + +- traefik_config_last_reload_success is the Unix time of the last successful + reload. It was stored as a float and read as 1.0 = success, so the page said + "Reload failed" on every scrape (#5355). The column becomes the moment; the + old values were timestamps misread, so they go with it. +- Routers are now graded on their last 15 minutes (routes.recent_window), + which reads the 4xx share too: the covering router index carries it, so + that read stays index-only. + +Revision ID: traefik_005_reload_at +Revises: traefik_004_covering_indexes +Create Date: 2026-10-08 +""" +from typing import Sequence, Union +from alembic import op +import sqlalchemy as sa + +revision: str = "traefik_005_reload_at" +down_revision: Union[str, None] = "traefik_004_covering_indexes" +branch_labels: Union[str, Sequence[str], None] = None +depends_on: Union[str, Sequence[str], None] = None + +_CHARTED = ["request_rate", "latency_p95_ms", "error_rate_5xx_pct"] + + +def upgrade() -> None: + op.drop_column("traefik_global_stats", "config_last_reload_success") + op.add_column("traefik_global_stats", + sa.Column("config_last_reload_at", sa.DateTime(timezone=True), nullable=True)) + op.drop_index("ix_traefik_metrics_router_scraped", "traefik_metrics") + op.create_index("ix_traefik_metrics_router_scraped", "traefik_metrics", ["router_name", "scraped_at"], + postgresql_include=_CHARTED + ["error_rate_4xx_pct"]) + + +def downgrade() -> None: + op.drop_index("ix_traefik_metrics_router_scraped", "traefik_metrics") + op.create_index("ix_traefik_metrics_router_scraped", "traefik_metrics", ["router_name", "scraped_at"], + postgresql_include=_CHARTED) + op.drop_column("traefik_global_stats", "config_last_reload_at") + op.add_column("traefik_global_stats", sa.Column("config_last_reload_success", sa.Float, nullable=True)) diff --git a/plugins/traefik/models.py b/plugins/traefik/models.py index 67c5bf7..bb1cb4c 100644 --- a/plugins/traefik/models.py +++ b/plugins/traefik/models.py @@ -63,5 +63,7 @@ class TraefikGlobalStat(Base): ) open_conns_total: Mapped[float | None] = mapped_column(Float, nullable=True) config_reloads_total: Mapped[float | None] = mapped_column(Float, nullable=True) - config_last_reload_success: Mapped[float | None] = mapped_column(Float, nullable=True) + # When Traefik last loaded its configuration successfully: its + # traefik_config_last_reload_success gauge is that moment, not a 0/1 flag. + config_last_reload_at: Mapped[datetime | None] = mapped_column(DateTime(timezone=True), nullable=True) process_memory_bytes: Mapped[float | None] = mapped_column(Float, nullable=True) diff --git a/plugins/traefik/routes.py b/plugins/traefik/routes.py index a3b836d..fd746ae 100644 --- a/plugins/traefik/routes.py +++ b/plugins/traefik/routes.py @@ -2,6 +2,7 @@ from __future__ import annotations from collections import defaultdict from datetime import datetime, timedelta, timezone +from types import SimpleNamespace from quart import Blueprint, current_app, render_template, request from sqlalchemy import func, select, text import json @@ -46,20 +47,71 @@ ERROR_4XX_PCT = 1.0 _GRADE_ORDER = {"crit": 0, "warn": 1, "ok": 2} -def router_state(latest, thresholds: dict) -> tuple[str, str | None]: - """(grade, why) for a router's latest scrape: crit while it serves 5xx, - warn on a p95 past the latency critical cutoff (Settings → Thresholds) - or a high 4xx share, otherwise ok with nothing to say.""" - if (latest.error_rate_5xx_pct or 0) > ERROR_5XX_PCT: - return "crit", f"{latest.error_rate_5xx_pct:.1f}% of responses are 5xx" - p95 = latest.latency_p95_ms +def router_state(reading, thresholds: dict, over: str = "") -> tuple[str, str | None]: + """(grade, why) for a router's reading (recent_window's, or one scrape's): + crit while it serves 5xx, warn on a p95 past the latency critical cutoff + (Settings → Thresholds) or a high 4xx share, otherwise ok with nothing to + say. `over` names the span the reading covers, for the why.""" + if (reading.error_rate_5xx_pct or 0) > ERROR_5XX_PCT: + return "crit", f"{reading.error_rate_5xx_pct:.1f}% of responses are 5xx{over}" + p95 = reading.latency_p95_ms if p95 is not None and status_class(p95, "latency", thresholds) == "crit": - return "warn", f"p95 latency is {p95:.0f} ms" - if (latest.error_rate_4xx_pct or 0) > ERROR_4XX_PCT: - return "warn", f"{latest.error_rate_4xx_pct:.1f}% of responses are 4xx" + return "warn", f"p95 latency is {p95:.0f} ms{over}" + if (reading.error_rate_4xx_pct or 0) > ERROR_4XX_PCT: + return "warn", f"{reading.error_rate_4xx_pct:.1f}% of responses are 4xx{over}" return "ok", None +# A router is graded on its last STATE_WINDOW of traffic, not on one scrape: +# a share near a cutoff crossed it on one scrape and fell back on the next, +# so problem cards came and went every poll (#5214). Over the window a real +# problem stays listed until it has been clean a while, and a one-scrape +# blip is diluted rather than shown. +STATE_WINDOW = timedelta(minutes=15) +STATE_WINDOW_WORDS = " over the last 15 min" + + +async def recent_window(db, names: list[str], now: datetime) -> dict[str, SimpleNamespace]: + """{router: one reading of its last STATE_WINDOW}: the 4xx and 5xx shares + weighted by each scrape's traffic (an idle scrape's 100% counts for + little), p95 averaged. A router with no rows in the window is absent.""" + if not names: + return {} + rate = TraefikMetric.request_rate + result = await db.execute( + select( + TraefikMetric.router_name, + func.sum(rate).label("req"), + func.sum(rate * TraefikMetric.error_rate_4xx_pct).label("e4w"), + func.sum(rate * TraefikMetric.error_rate_5xx_pct).label("e5w"), + func.avg(TraefikMetric.error_rate_4xx_pct).label("e4"), + func.avg(TraefikMetric.error_rate_5xx_pct).label("e5"), + func.avg(TraefikMetric.latency_p95_ms).label("p95"), + ) + .where(TraefikMetric.router_name.in_(names)) + .where(TraefikMetric.scraped_at >= now - STATE_WINDOW) + .group_by(TraefikMetric.router_name) + ) + out = {} + for r in result.all(): + req = r.req or 0.0 + out[r.router_name] = SimpleNamespace( + error_rate_4xx_pct=r.e4w / req if req > 0 else r.e4, + error_rate_5xx_pct=r.e5w / req if req > 0 else r.e5, + latency_p95_ms=r.p95, + ) + return out + + +def grade_routers(routers: list[dict], window: dict, thresholds: dict) -> None: + """Set each router's state and why from its recent window, or from its + latest scrape when the window holds nothing.""" + for r in routers: + reading = window.get(r["name"]) + r["state"], r["why"] = (router_state(reading, thresholds, STATE_WINDOW_WORDS) if reading + else router_state(r["latest"], thresholds)) + + # A router missing from this many scrapes in a row is no longer reported: # Traefik dropped it (a removed service), so its last state is history. GONE_AFTER_SCRAPES = 3 @@ -188,10 +240,11 @@ async def rows(): newest = await latest_per_router(db) current, gone = gone_routers([{"name": m.router_name, "latest": m} for m in newest], scrape) - history = await router_history(db, [r["name"] for r in current], since, bucket_seconds(since)) + names = [r["name"] for r in current] + history = await router_history(db, names, since, bucket_seconds(since)) + grade_routers(current, await recent_window(db, names, now), thresholds) for r in current: points = history[r["name"]] - r["state"], r["why"] = router_state(r["latest"], thresholds) r["sparkline_req"] = _sparkline([p.request_rate for p in points]) r["sparkline_p95"] = _sparkline([p.latency_p95_ms for p in points]) r["sparkline_5xx"] = _sparkline([p.error_rate_5xx_pct for p in points]) @@ -259,14 +312,15 @@ async def widget(): async with current_app.db_sessionmaker() as db: latest = await latest_per_router(db) + current, _gone = gone_routers([{"name": m.router_name, "latest": m} for m in latest], scrape) + window = await recent_window(db, [r["name"] for r in current], now) certs = (await db.execute(select(TraefikCert))).scalars().all() - current, _gone = gone_routers([{"name": m.router_name, "latest": m} for m in latest], scrape) served, _old = current_certs(certs, scrape) domains = router_domains() by_router = certs_by_router([r["name"] for r in current], domains or {}, served, now) + grade_routers(current, window, thresholds) for r in current: - r["state"], r["why"] = router_state(r["latest"], thresholds) r["cert"] = by_router.get(r["name"]) if r["cert"]: grade = status_class(r["cert"]["days"], "tls_days", thresholds) diff --git a/plugins/traefik/scraper.py b/plugins/traefik/scraper.py index fe0bf78..87cbdc5 100644 --- a/plugins/traefik/scraper.py +++ b/plugins/traefik/scraper.py @@ -152,21 +152,21 @@ def compute_router_metrics( def compute_global_stats( current: ParsedMetrics, previous: ParsedMetrics | None, -) -> dict[str, float | None]: +) -> dict[str, float | datetime | None]: """Extract process-level and config health metrics from a scrape. Returns: { "open_conns_total": float | None, "config_reloads_total": float | None, - "config_last_reload_success": float | None, # 1.0 = success, 0.0 = failure + "config_last_reload_at": datetime | None, # last successful reload "process_memory_bytes": float | None, } """ - stats: dict[str, float | None] = { + stats: dict[str, float | datetime | None] = { "open_conns_total": None, "config_reloads_total": None, - "config_last_reload_success": None, + "config_last_reload_at": None, "process_memory_bytes": None, } @@ -180,11 +180,15 @@ def compute_global_stats( if reloads: stats["config_reloads_total"] = sum(reloads.values()) - # Last reload success gauge + # The moment of the last successful reload, as a Unix timestamp: Traefik + # names it "last_reload_success", but it is a time, not a 0/1 flag. Read + # as a flag, every scrape said "Reload failed" (#5355). last_success = current.get("traefik_config_last_reload_success", {}) if last_success: # Usually a single sample with no labels - stats["config_last_reload_success"] = next(iter(last_success.values())) + ts = next(iter(last_success.values())) + if ts > 0: + stats["config_last_reload_at"] = datetime.fromtimestamp(ts, timezone.utc) # Process RSS memory mem = current.get("process_resident_memory_bytes", {}) diff --git a/plugins/traefik/templates/traefik/rows.html b/plugins/traefik/templates/traefik/rows.html index 421f2ce..ab5bb59 100644 --- a/plugins/traefik/templates/traefik/rows.html +++ b/plugins/traefik/templates/traefik/rows.html @@ -8,9 +8,8 @@ {{ stat_tile("Needs attention", problems|length, state="crit" if problems else "inactive") }} {{ stat_tile("Healthy routers", healthy|length, state="up" if healthy else "inactive") }} {% if global_stat %} - {% if global_stat.config_last_reload_success is not none %} - {{ stat_tile("Config", "OK" if global_stat.config_last_reload_success == 1.0 else "Reload failed", - state="up" if global_stat.config_last_reload_success == 1.0 else "crit", + {% if global_stat.config_last_reload_at %} + {{ stat_tile("Config reloaded", global_stat.config_last_reload_at|ago, hint=(global_stat.config_reloads_total|int ~ " reloads") if global_stat.config_reloads_total is not none else none) }} {% endif %} {% if global_stat.open_conns_total is not none %}{{ stat_tile("Open connections", global_stat.open_conns_total|int) }}{% endif %} diff --git a/tests/integration/test_traefik_latest.py b/tests/integration/test_traefik_latest.py index fa4508e..312e332 100644 --- a/tests/integration/test_traefik_latest.py +++ b/tests/integration/test_traefik_latest.py @@ -108,3 +108,34 @@ def test_router_history_reads_every_router_in_one_query_bucketed(app): assert got[a][0].latency_p95_ms == 20.0 assert [r.request_rate for r in got[b]] == [4.0] assert got[idle] == [] # its only row is before the range + + +def test_recent_window_weights_shares_by_traffic_and_keeps_to_the_window(app): + """#5214: a router is graded on its last 15 minutes. An idle scrape's + 100% 4xx counts for its trickle of traffic, not as a third of the + average; a row older than the window is not read.""" + from plugins.traefik.models import TraefikMetric + from plugins.traefik.routes import recent_window + + now = datetime(2097, 3, 1, 12, 0, tzinfo=timezone.utc) + timedelta(minutes=uuid.uuid4().int % 10_000) + tag = uuid.uuid4().hex[:8] + busy, empty = f"busy-{tag}@docker", f"empty-{tag}@docker" + + def row(name, ago, rate, e4, p95=10.0): + return TraefikMetric(router_name=name, scraped_at=now - timedelta(minutes=ago), request_rate=rate, + error_rate_4xx_pct=e4, error_rate_5xx_pct=0.0, latency_p50_ms=1.0, + latency_p95_ms=p95, latency_p99_ms=3.0, response_bytes_rate=0.0) + + async def go(): + async with app.db_sessionmaker() as s: + async with s.begin(): + s.add_all([row(busy, 1, 9.9, 0.0, 10.0), row(busy, 2, 0.1, 100.0, 30.0), + row(busy, 30, 50.0, 100.0), # outside the window + row(empty, 30, 1.0, 100.0)]) + async with s.begin(): + return await recent_window(s, [busy, empty], now) + + got = asyncio.run(go()) + assert set(got) == {busy} # nothing in empty's window + assert got[busy].error_rate_4xx_pct == pytest.approx(1.0) # 0.1 × 100 over 10 req/s + assert got[busy].latency_p95_ms == pytest.approx(20.0) diff --git a/tests/plugins/traefik/test_traefik_page.py b/tests/plugins/traefik/test_traefik_page.py index d94b44b..be51b8a 100644 --- a/tests/plugins/traefik/test_traefik_page.py +++ b/tests/plugins/traefik/test_traefik_page.py @@ -246,3 +246,42 @@ async def test_the_request_chart_says_its_figures_before_the_chart(app): assert "Requests/s (all routers)" in page and "max: 100" not in page assert "couldn't be drawn" in page # a failure says why in place of the chart assert "No Traefik requests recorded in the last 6h." in empty + + +def test_routers_are_graded_on_their_recent_window_not_one_scrape(): + """#5214: a 4xx share near the cutoff crossed it on one scrape and fell + back on the next, so problem cards came and went every poll.""" + from plugins.traefik.routes import STATE_WINDOW_WORDS, grade_routers + spiky, quiet = _latest(e4=1.5), _latest(e4=1.5) + routers = [{"name": "spiky", "latest": spiky}, {"name": "quiet", "latest": quiet}] + # spiky's last 15 min average well under the cutoff; quiet has no window rows. + grade_routers(routers, {"spiky": NS(error_rate_4xx_pct=0.4, error_rate_5xx_pct=0.0, latency_p95_ms=20.0)}, TH) + assert routers[0]["state"] == "ok" + assert routers[1]["state"] == "warn" and not routers[1]["why"].endswith(STATE_WINDOW_WORDS) + held = [{"name": "held", "latest": _latest()}] # clean now, bad over the window + grade_routers(held, {"held": NS(error_rate_4xx_pct=3.0, error_rate_5xx_pct=0.0, latency_p95_ms=20.0)}, TH) + assert held[0]["state"] == "warn" + assert held[0]["why"] == "3.0% of responses are 4xx over the last 15 min" + + +def test_the_last_reload_gauge_is_a_moment_not_a_flag(): + """#5355: traefik_config_last_reload_success is a Unix time; read as a + 0/1 flag it said "Reload failed" on every scrape.""" + from plugins.traefik.scraper import compute_global_stats + at = compute_global_stats({"traefik_config_last_reload_success": {frozenset(): 1791460000.0}, + "traefik_config_reloads_total": {frozenset(): 343.0}}, None) + assert at["config_last_reload_at"] == datetime.fromtimestamp(1791460000.0, timezone.utc) + assert at["config_reloads_total"] == 343.0 + never = compute_global_stats({"traefik_config_last_reload_success": {frozenset(): 0.0}}, None) + assert never["config_last_reload_at"] is None + + +async def test_the_config_tile_says_when_it_last_reloaded(app): + stat = NS(config_last_reload_at=datetime.now(timezone.utc) - timedelta(minutes=3), + config_reloads_total=343.0, open_conns_total=None, process_memory_bytes=None) + async with app.test_request_context("/plugins/traefik/rows"): + page = await render_plugin_template(app, "traefik", "traefik/rows.html", problems=[], healthy=[], + gone=[], global_stat=stat, certs=[], old_certs=[], range_key="24h", + error_4xx=1.0, error_5xx=0.1) + assert "Config reloaded" in page and "3m ago" in page and "343 reloads" in page + assert "Reload failed" not in page