From eb02603092be5510e48dc32ff0f99959ec954a38 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 25 May 2026 00:31:05 -0400 Subject: [PATCH] feat: diagnostic instrumentation for crash investigation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Recurring app/db crashes with no clear cause in existing logs. Adds three crash-class indicators with minimal overhead (~1 log line/min, 0.1ms work per heartbeat). services/diagnostics.py: 1. **Heartbeat** every 60s logs a snapshot: - RSS memory (from /proc/self/status — no deps). - asyncio task count. - DB pool: size / checked_in / checked_out / overflow. - Curator busy state (from is_curator_running()). - Uptime. A sudden silence in heartbeats bounds the crash time to within 60s. The last snapshot before silence usually rules in or out: memory growth -> OOM, pool exhaustion -> connection leak, hung curator -> stuck async task. 2. **Signal handler** for SIGTERM/SIGINT logs the signal name + final snapshot before letting Hypercorn handle the actual shutdown. Distinguishes 'orderly shutdown via signal X' from 'silent log gap then container exit code 137' (SIGKILL / OOM-kill are uncatchable; their absence in our log IS the diagnostic). 3. **Asyncio exception hook** logs full tracebacks for unhandled task exceptions with the task/coro name. Default behaviour swallows these silently — exactly the pattern that locked us out of chat at 409 for an hour back on 2026-05-22 before we added the guard around run_generation. app.py wires start_diagnostics() into before_serving and stop_diagnostics() into after_serving. stop_diagnostics emits one final snapshot so the silence that follows is intentional, not a crash. How to use the new logs to diagnose: - App restarts with 'received SIGTERM' in the last lines: Orderly shutdown (docker stop / swarm restart / manual). Look upstream for who issued it. - App restarts with no shutdown line, last heartbeat 30+s before: Likely SIGKILL — OOM-kill or container resource limit. Check 'docker ps -a' for exit code 137, or 'dmesg | grep -i kill' on host. - App restarts with no shutdown line, heartbeat showed climbing RSS: Memory leak. Snapshot the last heartbeat's MB value vs earlier — if it doubled over hours, OOM is the cause. - App restarts, db_pool checked_out kept growing: Connection leak. Look for code paths that open async_session() but never exit the 'async with' block. - App seemed alive but stopped responding to requests, heartbeats continued: Curator hung holding _CURATOR_RUN_LOCK. Check curator_busy=true across multiple heartbeats — if stuck >5min, the Ollama call hung. Restart Ollama or the Scribe stack. Co-Authored-By: Claude Opus 4.7 (1M context) --- src/fabledassistant/app.py | 8 + src/fabledassistant/services/diagnostics.py | 243 ++++++++++++++++++++ 2 files changed, 251 insertions(+) create mode 100644 src/fabledassistant/services/diagnostics.py diff --git a/src/fabledassistant/app.py b/src/fabledassistant/app.py index 238fc08..58bb9a7 100644 --- a/src/fabledassistant/app.py +++ b/src/fabledassistant/app.py @@ -348,6 +348,12 @@ def create_app() -> Quart: from fabledassistant.services.curator_scheduler import start_curator_scheduler start_curator_scheduler(asyncio.get_running_loop()) + # Diagnostic instrumentation — heartbeat, signal handlers, asyncio + # exception hook. Cheap (~1 log line/min), high diagnostic value when + # the app crashes mysteriously. See services/diagnostics.py. + from fabledassistant.services.diagnostics import start_diagnostics + start_diagnostics(asyncio.get_running_loop()) + # Voice model loading (enabled via Admin → Config in the UI, or VOICE_ENABLED env var) from fabledassistant.services.stt import load_stt_model from fabledassistant.services.tts import load_tts_model @@ -366,6 +372,8 @@ def create_app() -> Quart: stop_version_pinning_scheduler() from fabledassistant.services.curator_scheduler import stop_curator_scheduler stop_curator_scheduler() + from fabledassistant.services.diagnostics import stop_diagnostics + stop_diagnostics() @app.route("/") async def serve_index(): diff --git a/src/fabledassistant/services/diagnostics.py b/src/fabledassistant/services/diagnostics.py new file mode 100644 index 0000000..92f758b --- /dev/null +++ b/src/fabledassistant/services/diagnostics.py @@ -0,0 +1,243 @@ +"""Lightweight diagnostic instrumentation for crash investigation. + +The Scribe app + its Postgres have been crashing recurrently with no +clear cause in the logs. This module adds three things designed to make +the crash class identifiable from logs alone: + +1. **Heartbeat** — once per minute, log a snapshot of process resources + (RSS memory, asyncio task count, DB pool checked-in/out, curator + busy state). A sudden silence in heartbeats lets you bound the + crash time to within a minute, and the last snapshot before silence + usually rules in or out memory growth / pool exhaustion / hung + curator pass. + +2. **Signal handler** — catches SIGTERM and SIGINT, logs them with the + sender's intent ("docker stop", "swarm restart", "manual ctrl-C") + then lets the normal shutdown proceed. Distinguishes orderly + shutdown from kill-9 / OOM-kill (which can't be caught and will + show as a silent log gap followed by container exit code 137). + +3. **Asyncio exception hook** — every Task that raises an uncaught + exception logs a full traceback. Without this, `asyncio.create_task` + exceptions are swallowed silently — the chat crash that locked us + into 409 forever was exactly this pattern. + +All three are read-only / log-only — no behavior changes. Safe to +leave running in production indefinitely; the cost is one log line +per minute and ~0.1ms of work per heartbeat. +""" +from __future__ import annotations + +import asyncio +import logging +import os +import signal +import time +from typing import Any + +logger = logging.getLogger(__name__) + +# Heartbeat cadence. 60s is the sweet spot: short enough that a crash +# window is bounded to a useful interval, long enough that the log +# noise is negligible. If we ever need more resolution during active +# debugging, drop it temporarily to 15s. +_HEARTBEAT_INTERVAL_SECS = 60 + +_heartbeat_task: asyncio.Task | None = None +_shutdown_logged = False # don't double-log shutdown if multiple signals arrive +_started_at: float | None = None + + +def _process_rss_mb() -> float | None: + """Resident-set memory in MB. Read from /proc/self/status — no deps.""" + try: + with open("/proc/self/status") as fh: + for line in fh: + if line.startswith("VmRSS:"): + # Format: 'VmRSS: 123456 kB' + kb = int(line.split()[1]) + return round(kb / 1024, 1) + except Exception: + pass + return None + + +def _db_pool_stats() -> dict[str, Any]: + """Pool checked-in / checked-out / overflow. Direct from SQLAlchemy.""" + try: + from fabledassistant.models import engine + pool = engine.pool + # Async engines wrap a sync pool; .checkedin() / .checkedout() exist + # on the underlying QueuePool. Attribute access is documented but + # version-fragile, so wrap in try. + return { + "size": getattr(pool, "size", lambda: None)(), + "checked_in": getattr(pool, "checkedin", lambda: None)(), + "checked_out": getattr(pool, "checkedout", lambda: None)(), + "overflow": getattr(pool, "overflow", lambda: None)(), + } + except Exception: + return {} + + +def _asyncio_task_count() -> int | None: + try: + return len([t for t in asyncio.all_tasks() if not t.done()]) + except Exception: + return None + + +def _curator_busy() -> bool | None: + try: + from fabledassistant.services.curator import is_curator_running + return is_curator_running() + except Exception: + return None + + +def _uptime_secs() -> float | None: + if _started_at is None: + return None + return round(time.monotonic() - _started_at, 1) + + +async def _heartbeat_loop() -> None: + """Forever-running task that emits one snapshot per interval. + + Exceptions inside the loop are caught and logged so the loop itself + can't die silently — the whole point is that this thing keeps + talking even when other things crash around it. + """ + while True: + try: + rss = _process_rss_mb() + tasks = _asyncio_task_count() + curator = _curator_busy() + pool = _db_pool_stats() + uptime = _uptime_secs() + logger.info( + "diag heartbeat: uptime=%ss rss=%sMB asyncio_tasks=%s " + "db_pool=%s curator_busy=%s", + uptime, rss, tasks, pool, curator, + ) + except Exception: + logger.exception("Heartbeat snapshot crashed (continuing)") + try: + await asyncio.sleep(_HEARTBEAT_INTERVAL_SECS) + except asyncio.CancelledError: + logger.info("diag heartbeat: shutting down (CancelledError)") + raise + + +def _asyncio_exception_handler(loop: asyncio.AbstractEventLoop, context: dict) -> None: + """Log unhandled task exceptions instead of letting them disappear. + + Default asyncio behaviour: if a fire-and-forget task raises and + nothing awaits the result, the exception is logged at ERROR but the + surrounding context (which task, what coroutine) can be sparse. + This handler enriches the log line so we can tell WHICH task crashed. + """ + msg = context.get("message", "") + exc = context.get("exception") + task = context.get("task") or context.get("future") + task_name = getattr(task, "get_name", lambda: "?")() if task else "?" + coro = getattr(task, "get_coro", lambda: None)() if task else None + coro_name = getattr(coro, "__qualname__", str(coro)) if coro else "?" + + if exc is not None: + logger.error( + "asyncio unhandled exception in task %r (coro=%s): %s", + task_name, coro_name, msg, + exc_info=(type(exc), exc, exc.__traceback__), + ) + else: + logger.error( + "asyncio unhandled event in task %r (coro=%s): %s — context=%r", + task_name, coro_name, msg, context, + ) + + +def _signal_handler(loop: asyncio.AbstractEventLoop, signame: str) -> None: + """Catch SIGTERM/SIGINT and log them. + + Doesn't try to interfere with shutdown — Hypercorn handles its own + graceful exit. We just want a log line so we can tell "orderly + shutdown via signal X" apart from "silent gap then container exit" + (which means kill-9 or OOM, neither of which is catchable). + """ + global _shutdown_logged + if _shutdown_logged: + return + _shutdown_logged = True + logger.warning( + "diag shutdown: received %s, expecting graceful exit " + "(uptime=%ss, asyncio_tasks=%s, rss=%sMB, db_pool=%s)", + signame, + _uptime_secs(), + _asyncio_task_count(), + _process_rss_mb(), + _db_pool_stats(), + ) + + +def start_diagnostics(loop: asyncio.AbstractEventLoop) -> None: + """Install all three diagnostic surfaces. Idempotent.""" + global _heartbeat_task, _started_at + + if _started_at is None: + _started_at = time.monotonic() + + # 1. Asyncio exception hook — install once. + if loop.get_exception_handler() is None: + loop.set_exception_handler(_asyncio_exception_handler) + + # 2. Signal handlers. add_signal_handler is Unix-only; skip on + # Windows so dev on a non-Linux machine doesn't blow up. + if os.name == "posix": + for sig in (signal.SIGTERM, signal.SIGINT): + try: + loop.add_signal_handler( + sig, + _signal_handler, + loop, + sig.name, + ) + except (RuntimeError, NotImplementedError, ValueError): + # add_signal_handler can fail when not running in the main + # thread or when the loop is already managing the signal. + # Either case is fine — heartbeat + exception hook still work. + pass + + # 3. Heartbeat loop. Start if not already running (idempotent on + # restart-style reloads). + if _heartbeat_task is None or _heartbeat_task.done(): + _heartbeat_task = asyncio.create_task( + _heartbeat_loop(), name="diag-heartbeat", + ) + logger.info( + "diag started: heartbeat every %ds, signal-aware shutdown logging on, " + "asyncio exception hook installed", + _HEARTBEAT_INTERVAL_SECS, + ) + + +def stop_diagnostics() -> None: + """Cancel the heartbeat. Called from after_serving. + + Lets the loop emit one last 'shutting down' log line so the silence + that follows is intentional (not a crash). The exception hook stays + installed but won't fire after the loop closes. + """ + global _heartbeat_task + if _heartbeat_task is not None and not _heartbeat_task.done(): + _heartbeat_task.cancel() + _heartbeat_task = None + logger.info( + "diag stopped: heartbeat cancelled. Final snapshot: " + "uptime=%ss rss=%sMB asyncio_tasks=%s db_pool=%s curator_busy=%s", + _uptime_secs(), + _process_rss_mb(), + _asyncio_task_count(), + _db_pool_stats(), + _curator_busy(), + )