fix(web): report a corrupt state.db as a throttled 503 status instead of a traceback per poll
The dashboard polls /api/analytics/usage and /api/analytics/models every
few seconds. When state.db is malformed the read raised straight through
the handler, so uvicorn logged a full traceback at ERROR on every poll —
one fleet host wrote ~520K identical journal entries in 24 h.
Wrap both analytics handlers in `corrupt_store_as_status`: a corrupt-image
sqlite3.DatabaseError (is_malformed_db_error) becomes a 503 with an
explicit `state_db_corrupt` payload pointing at `hermes doctor`, and the
warning is gated per store path via `{path: monotonic}` (>=300 s), then
debug. Busy/locked and every other error propagate unchanged, and the file
is never renamed or quarantined from the dashboard — repair stays with
`hermes doctor` / `hermes sessions repair`. `_session_db_path_for_profile`
is split out of `_open_session_db_for_profile` so the router can name the
store without opening it.
Refs #96591
Reported-by: #96591
This commit is contained in:
@@ -7,7 +7,9 @@ from __future__ import annotations
|
||||
import asyncio
|
||||
import contextlib
|
||||
import logging
|
||||
from typing import Any, Callable, Optional
|
||||
import sqlite3
|
||||
import time
|
||||
from typing import Any, Callable, Dict, Optional
|
||||
|
||||
from fastapi import HTTPException
|
||||
|
||||
@@ -76,3 +78,39 @@ def require(value: Optional[str], detail: str) -> str:
|
||||
if not stripped:
|
||||
raise HTTPException(status_code=400, detail=detail)
|
||||
return stripped
|
||||
|
||||
|
||||
# Corrupt-store reporting for polled read endpoints. The dashboard polls analytics every few
|
||||
# seconds; a persistently malformed state.db once produced ~520K identical tracebacks in 24 h
|
||||
# (#96591). One WARNING per store per interval, then debug; the caller gets an explicit status
|
||||
# instead of a 500. The file is never quarantined or renamed from here — that is `hermes doctor`'s job.
|
||||
_CORRUPT_STORE_WARN_INTERVAL_S = 300.0
|
||||
_corrupt_store_warned_at: Dict[str, float] = {} # {db path: monotonic}
|
||||
|
||||
CORRUPT_STORE_DETAIL = {
|
||||
"error": "state_db_corrupt",
|
||||
"message": "state.db corrupt — run `hermes doctor` (then `hermes doctor --fix` or `hermes sessions repair`).",
|
||||
}
|
||||
|
||||
|
||||
@contextlib.contextmanager
|
||||
def corrupt_store_as_status(db_path):
|
||||
"""Map a corrupt-image ``sqlite3.DatabaseError`` from a state.db read to a 503 status
|
||||
payload, warning once per store per :data:`_CORRUPT_STORE_WARN_INTERVAL_S`.
|
||||
Busy/locked and every other error propagate unchanged."""
|
||||
from hermes_state_errors import is_malformed_db_error
|
||||
|
||||
try:
|
||||
yield
|
||||
except sqlite3.DatabaseError as exc:
|
||||
if not is_malformed_db_error(exc):
|
||||
raise
|
||||
key, now = str(db_path), time.monotonic()
|
||||
last = _corrupt_store_warned_at.get(key)
|
||||
if last is None or now - last >= _CORRUPT_STORE_WARN_INTERVAL_S:
|
||||
_corrupt_store_warned_at[key] = now
|
||||
log.warning("state.db at %s is corrupt (%s); dashboard reads return a status payload until it is "
|
||||
"repaired — run `hermes doctor`", db_path, exc)
|
||||
else:
|
||||
log.debug("state.db at %s still corrupt: %s", db_path, exc)
|
||||
raise HTTPException(status_code=503, detail={**CORRUPT_STORE_DETAIL, "path": key}) from exc
|
||||
|
||||
@@ -13,6 +13,7 @@ from fastapi import APIRouter, HTTPException, Query
|
||||
|
||||
from hermes_cli.config import get_config_path, read_raw_config
|
||||
from hermes_cli.web_deps import late
|
||||
from hermes_cli.web_routers._common import corrupt_store_as_status
|
||||
from hermes_cli.web_server_profiles import (
|
||||
_approval_mode_of, _aux_task_summary, _aux_usage_rows, _broadcast_gateway_session_info, _is_other_profile, _merge_aux_into_by_model,
|
||||
)
|
||||
@@ -22,6 +23,7 @@ router = APIRouter()
|
||||
|
||||
# Late-bound so a test's monkeypatch on the owning module wins at call time.
|
||||
_open_session_db_for_profile = late("_open_session_db_for_profile", "hermes_cli.web_server_sessions")
|
||||
_session_db_path_for_profile = late("_session_db_path_for_profile", "hermes_cli.web_server_sessions")
|
||||
_profile_scope = late("_profile_scope", "hermes_cli.web_server_profiles")
|
||||
save_config = late("save_config", "hermes_cli.config")
|
||||
|
||||
@@ -147,7 +149,8 @@ async def get_usage_analytics(
|
||||
values would force expensive full-history SQL and InsightsEngine work, or
|
||||
produce empty/inverted time windows. The UI only offers 7/30/90-day
|
||||
presets."""
|
||||
return await asyncio.to_thread(_get_usage_analytics, days, profile)
|
||||
with corrupt_store_as_status(_session_db_path_for_profile(profile)):
|
||||
return await asyncio.to_thread(_get_usage_analytics, days, profile)
|
||||
|
||||
|
||||
_USAGE_KEYS = (
|
||||
@@ -305,4 +308,5 @@ async def get_models_analytics(
|
||||
profile: Optional[str] = None,
|
||||
):
|
||||
"""Return model analytics without blocking the serving event loop."""
|
||||
return await asyncio.to_thread(_get_models_analytics, days, profile)
|
||||
with corrupt_store_as_status(_session_db_path_for_profile(profile)):
|
||||
return await asyncio.to_thread(_get_models_analytics, days, profile)
|
||||
|
||||
@@ -180,20 +180,23 @@ def _open_session_db_at_path(db_path: Path, *, read_only: bool):
|
||||
return _open_probed()
|
||||
|
||||
|
||||
def _open_session_db_for_profile(profile: Optional[str], *, read_only: bool):
|
||||
"""Open a SessionDB for ``profile`` (None/empty = this process's own state.db).
|
||||
|
||||
Access-mode semantics: see :func:`_open_session_db_at_path`.
|
||||
"""
|
||||
def _session_db_path_for_profile(profile: Optional[str]) -> Path:
|
||||
"""state.db path for ``profile`` (None/empty = this process's own)."""
|
||||
from hermes_cli.web_server_cron import _cron_profile_home
|
||||
from hermes_state import _default_db_path
|
||||
|
||||
if profile:
|
||||
_name, home = _cron_profile_home(profile)
|
||||
db_path = Path(home) / "state.db"
|
||||
else:
|
||||
db_path = Path(_default_db_path())
|
||||
return _open_session_db_at_path(db_path, read_only=read_only)
|
||||
return Path(home) / "state.db"
|
||||
return Path(_default_db_path())
|
||||
|
||||
|
||||
def _open_session_db_for_profile(profile: Optional[str], *, read_only: bool):
|
||||
"""Open a SessionDB for ``profile`` (None/empty = this process's own state.db).
|
||||
|
||||
Access-mode semantics: see :func:`_open_session_db_at_path`.
|
||||
"""
|
||||
return _open_session_db_at_path(_session_db_path_for_profile(profile), read_only=read_only)
|
||||
|
||||
|
||||
# In-process throttle for the opportunistic auto-archive trigger, keyed by
|
||||
|
||||
@@ -0,0 +1,57 @@
|
||||
"""A malformed state.db must not turn dashboard analytics polling into a traceback storm (#96591)."""
|
||||
import logging
|
||||
import sqlite3
|
||||
from pathlib import Path
|
||||
|
||||
import pytest
|
||||
from fastapi import FastAPI
|
||||
from fastapi.testclient import TestClient
|
||||
|
||||
from hermes_cli.web_routers import _common, analytics
|
||||
from hermes_state import SessionDB
|
||||
|
||||
|
||||
def _malformed_state_db(home: Path) -> Path:
|
||||
db_path = home / "state.db"
|
||||
db = SessionDB(db_path=db_path)
|
||||
db.create_session("s1", source="cli", model="m")
|
||||
db.close()
|
||||
for side in ("-wal", "-shm"):
|
||||
Path(str(db_path) + side).unlink(missing_ok=True)
|
||||
with open(db_path, "r+b") as f:
|
||||
f.seek(100)
|
||||
f.write(b"\xff" * (4096 - 100))
|
||||
with pytest.raises(sqlite3.DatabaseError):
|
||||
sqlite3.connect(str(db_path)).execute("SELECT count(*) FROM sqlite_master")
|
||||
return db_path
|
||||
|
||||
|
||||
def test_corrupt_store_polls_return_status_and_warn_once_per_interval(tmp_path, monkeypatch, caplog):
|
||||
monkeypatch.setenv("HERMES_HOME", str(tmp_path))
|
||||
import hermes_state
|
||||
db_path = _malformed_state_db(tmp_path)
|
||||
monkeypatch.setattr(hermes_state, "_default_db_path", lambda: db_path)
|
||||
monkeypatch.setattr(_common, "_corrupt_store_warned_at", {})
|
||||
app = FastAPI()
|
||||
app.include_router(analytics.router)
|
||||
client = TestClient(app)
|
||||
|
||||
with caplog.at_level(logging.DEBUG, logger="hermes_cli.web_server"):
|
||||
first = client.get("/api/analytics/usage?days=7")
|
||||
second = client.get("/api/analytics/usage?days=7")
|
||||
third = client.get("/api/analytics/models?days=7")
|
||||
for resp in (first, second, third):
|
||||
assert resp.status_code == 503
|
||||
assert resp.json()["detail"]["error"] == "state_db_corrupt"
|
||||
assert "hermes doctor" in resp.json()["detail"]["message"]
|
||||
warnings = [r for r in caplog.records if r.levelno >= logging.WARNING]
|
||||
assert len(warnings) == 1, [r.getMessage() for r in warnings]
|
||||
assert not any(r.exc_info for r in caplog.records), "no tracebacks for a known corrupt store"
|
||||
assert db_path.exists() and db_path.stat().st_size > 0, "dashboard must never quarantine the file"
|
||||
|
||||
# The gate re-arms once the interval has elapsed (aged, not slept).
|
||||
_common._corrupt_store_warned_at[str(db_path)] -= _common._CORRUPT_STORE_WARN_INTERVAL_S + 1
|
||||
caplog.clear()
|
||||
with caplog.at_level(logging.WARNING, logger="hermes_cli.web_server"):
|
||||
assert client.get("/api/analytics/usage?days=7").status_code == 503
|
||||
assert sum(r.levelno >= logging.WARNING for r in caplog.records) == 1
|
||||
Reference in New Issue
Block a user