Skip to content

Capture asyncio/alembic/warnings logs and install crash hooks - #1466

Merged
Tim020 merged 6 commits into
feature/obs-health-checkfrom
feature/obs-capture-stdlib-logs
Oct 22, 2026
Merged

Tim020 merged 6 commits into
feature/obs-health-checkfrom
feature/obs-capture-stdlib-logs

Conversation

@Tim020

@Tim020 Tim020 commented Oct 22, 2026

Copy link
Copy Markdown
Contributor

Summary

  • Add asyncio, alembic and py.warnings to ALL_LOGGERS so file handler, server log buffer and level config cover them (root logger and sqlalchemy.engine untouched).
  • New install_exception_hooks(loop) (idempotent) installs sys.excepthook, threading.excepthook and an asyncio loop exception handler, enables logging.captureWarnings, and increments digiscript_unhandled_errors_total{source} (sys_excepthook|asyncio|thread). Called from main().
  • Note: IOLoop.add_callback already catches and logs exceptions to tornado.application; the loop handler covers raw asyncio callbacks and unretrieved task exceptions.

Test plan

  • pytest (1165 passed), ruff check/format
  • Full Playwright suite (225 passed)
  • Server smoke boot/terminate

🤖 Generated with Claude Code

@Tim020 Tim020 added the claude Issues created by Claude label Oct 22, 2026
@github-actions github-actions Bot added server Pull requests changing back end code medium-diff labels Oct 22, 2026
@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Client V3 Test Results

227 tests   227 ✅  0s ⏱️
 20 suites    0 💤
  1 files      0 ❌

Results for commit 5998f6a.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Client Test Results

102 tests  ±0   102 ✅ ±0   0s ⏱️ ±0s
  9 suites ±0     0 💤 ±0 
  1 files   ±0     0 ❌ ±0 

Results for commit 5998f6a. ± Comparison against base commit d7a71dd.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Python Test Results

    1 files      1 suites   1m 7s ⏱️
1 220 tests 1 220 ✅ 0 💤 0 ❌
1 243 runs  1 243 ✅ 0 💤 0 ❌

Results for commit 5998f6a.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Playwright E2E Results (firefox)

227 tests   227 ✅  2m 21s ⏱️
 14 suites    0 💤
  1 files      0 ❌

Results for commit 5998f6a.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Playwright E2E Results (chromium)

227 tests   227 ✅  2m 18s ⏱️
 14 suites    0 💤
  1 files      0 ❌

Results for commit 5998f6a.

♻️ This comment has been updated with latest results.

Route asyncio/alembic/py.warnings through the same file, buffer and level
handling as the DigiScript loggers, and install sys/threading/asyncio
exception hooks that log tracebacks and increment
digiscript_unhandled_errors_total{source}.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
@Tim020
Tim020 force-pushed the feature/obs-capture-stdlib-logs branch from 207f229 to 41cf074 Compare October 22, 2026 17:46
@Tim020
Tim020 changed the base branch from dev to feature/obs-health-check October 22, 2026 17:47
@Tim020
Tim020 added this pull request to stack #1468 October 22, 2026 17:48
@Tim020
Tim020 marked this pull request as ready for review October 22, 2026 17:52

@Tim020 Tim020 left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review round 1

Head SHA reviewed: 41cf074bafc02bc0ca8adcdd7da7256419434fa0

Verdict: Changes suggested, not blocking. The core design is sound and well tested for its happy paths, but there are several correctness/robustness gaps worth fixing before merge, particularly around the exception-hook install/uninstall lifecycle.

Previous round follow-up: N/A — this is round 1, no prior threads.

SonarQube: Quality gate PASSED (new_reliability_rating, new_security_rating, new_maintainability_rating all A; 0% duplication; 100% security hotspots reviewed; 0 security hotspots found). 2 open code smells on new code, both in server/test/digi_server/test_logger.py (1 minor, 1 major), neither gate-blocking — posted inline below. Source: anonymous SonarCloud API (public project), confirmed fresh against this PR's head SHA.

New findings: 6 Important, 3 Suggestion.

  • Important: non-atomic install race that can self-corrupt hook state and cause a RecursionError on KeyboardInterrupt (logger.py:94-98); uninstall_exception_hooks() doesn't save/restore the loop's previous exception handler (logger.py:100-114); sys/threading hooks replace rather than chain to any pre-existing hook, inconsistently with each other (logger.py:44-62); _asyncio_exception_handler treats message-only contexts as unhandled errors and has no defensive wrapper around repr()-based extras construction (logger.py:65-78); and a test (test_warnings_reach_py_warnings_logger_once) that passes regardless of whether the production captureWarnings call works, because it redundantly re-enables capture itself (test_logger.py:219).
  • Suggestion: uninstall_exception_hooks() unconditionally disables warning capture instead of restoring prior state (logger.py:114); hooks are armed before any log handler is attached at startup (main.py:58); two SonarQube maintainability smells in the test file (test_logger.py:94, test_logger.py:123).

All findings anchored to diff lines inline below; none require anchoring in this summary.

Strengths:

  • Clear problem framing and a minimal, focused diff (one module, one call site, matching tests).
  • Counter increments happen before the risky logging calls in all three hooks, so metrics survive even if the log line itself fails.
  • Good targeted regression test for the subtle IOLoop.add_callback vs. raw call_soon interaction, and a deterministic GC-forcing test for the "Task exception was never retrieved" path.
  • ruff check/ruff format --check clean; full test file passes (18/18) at head.

🤖 Generated with Claude Code

Comment thread server/digi_server/logger.py Outdated
Comment thread server/digi_server/logger.py Outdated
Comment thread server/digi_server/logger.py Outdated
Comment thread server/digi_server/logger.py Outdated
Comment thread server/digi_server/logger.py Outdated
Comment thread server/main.py


async def main():
install_exception_hooks(asyncio.get_running_loop())

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggestion: install_exception_hooks(...) runs as the very first line of main(), before parse_command_line() and well before DigiScriptServer.configure() attaches the rotating file handler / in-memory log buffer (much later, in app_server.py). Any exception the new hooks catch during that window is logged via logger.critical/logger.error to loggers with no handlers attached yet — Python's logging.lastResort still prints it to stderr, and the Prometheus counter still increments, so it's not fully silent, but it won't land in the durable, queryable log this PR is meant to provide. Low practical risk given how little runs before configuration, but worth being aware of.

🤖 Generated with Claude Code

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed — this was a Suggestion, not a blocker, and documenting the tradeoff in the comment at main.py:58-61 (early crashes are counted and reach stderr, but not the file log until configure() runs) is a reasonable resolution. No further action needed from my side.

🤖 Generated with Claude Code

Comment thread server/test/digi_server/test_logger.py Outdated
Comment thread server/test/digi_server/test_logger.py Outdated

def test_sys_excepthook_keeps_default_for_keyboard_interrupt(self):
calls = []
sys.excepthook = lambda *a: calls.append(a)

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggestion [SonarQube: python:S8997]: Sonar flags the direct mutation of sys.excepthook here as global-state mutation that should go through a fixture (e.g. pytest's monkeypatch) for automatic restoration. That doesn't quite fit this file as-is — it uses unittest.TestCase/IsolatedAsyncioTestCase classes throughout (matching the pre-existing TestMapClientLevel class in the same file), not bare pytest functions, and the class's own setUp/tearDown already snapshots and restores sys.excepthook for every test, including this one. Switching just this one assignment to monkeypatch would mean mixing fixture-based and class-based patterns in the same file. Flagging for awareness; I wouldn't block on it given the existing file convention.

🤖 Generated with Claude Code

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed — this matches the caveat I noted in my original comment. This file's unittest.TestCase/IsolatedAsyncioTestCase classes already snapshot and restore sys.excepthook/threading.excepthook in setUp/tearDown, so a monkeypatch-based fixture would mix patterns rather than add safety. Not blocking.

Note: SonarCloud is now flagging this same rule (python:S8997) on four more lines added in this round's new tests (test_logger.py:147,242,243,279) — same pattern, same reasoning applies, so I'm not opening new threads for those; flagging here for visibility in case you want to mark them "won't fix" in SonarCloud directly.

🤖 Generated with Claude Code

…gistered metric

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
@Tim020

Tim020 commented Oct 22, 2026

Copy link
Copy Markdown
Contributor Author

Review round 1 addressed in 39ecb7b:

  • Non-atomic install / self-referential saved hook (RecursionError): fixed. An RLock guards install/uninstall, the hooks never save themselves, and tests cover concurrent install and re-install cycles.
  • Uninstall not restoring the loop handler: fixed. Previous handlers are saved per loop and restored on uninstall if the loop is open and still ours.
  • sys/threading hooks not chaining: fixed. Both now chain consistently to any pre-existing non-default hook after logging, skipping the interpreter defaults to avoid duplicate stderr output. A broken chained hook cannot mask the crash.
  • Message-only asyncio contexts counted as errors: fixed. They are logged at WARNING and not counted, and the handler is defensively wrapped (safe repr, falls back to the default handler).
  • test_warnings_reach_py_warnings_logger_once calling captureWarnings itself: fixed. The test now relies on the production install call.
  • Uninstall hardcoding captureWarnings(False): fixed. The prior state is now restored.
  • main.py hook ordering: kept, and documented in a comment. Early crashes are counted and reach stderr, but not the file log until configure() runs.
  • Sonar S5906 (assertLessEqual): fixed.
  • Sonar S8997 (monkeypatch): rejected. These are unittest.TestCase classes whose setUp/tearDown already snapshot and restore the hooks, so a pytest fixture does not fit the file's convention.
  • Cross-cutting from Add Prometheus/Grafana monitoring overlay and docs #1462: the three label series (sys_excepthook, asyncio, thread) are now pre-registered at import, with a test that they exist before any error.

Local checks: pytest 1182 passed; ruff check and format are clean.

@Tim020 Tim020 left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review round 2

Head SHA reviewed: 5dca16f8d73e4d5c204bdb4916190a431a7b242f (incremental diff since round 1: 41cf074b..5dca16f8)

Verdict: Ready to merge once the one Important item below is addressed (or at your discretion — it concerns test robustness, not production correctness). All round-1 production-code findings are genuinely fixed and well-tested; the fix-up commit (39ecb7b) is solid.

Previous round follow-up: 7 verified fixed and resolved; 2 accepted with no code change needed (author's explanation was convincing in both cases) — left unresolved for your own housekeeping, not re-raised:

  • Fixed & resolved: non-atomic install race (_hooks_lock + install-time self-ref guards, tested by test_concurrent_install_is_race_free/test_keyboard_interrupt_does_not_recurse_after_reinstall); uninstall not restoring the loop handler (_saved_loop_handlers, tested by test_uninstall_restores_loop_handler); hooks not chaining to pre-existing hooks (_chain(), tested by test_hooks_chain_to_preexisting_hooks); asyncio handler miscounting message-only contexts + no repr safety net (_safe_repr, tested by test_message_only_context_not_counted_as_error/test_asyncio_handler_survives_failing_repr); uninstall hardcoding captureWarnings(False) (now restores prior state, tested by test_uninstall_restores_warning_capture_state); test that didn't test its own claim (test_warnings_reach_py_warnings_logger_once no longer self-enables capture); Sonar S5906 (assertLessEqual).
  • Accepted, not resolved: main.py startup-ordering Suggestion — kept and documented rather than changed, which I agree is reasonable for a Suggestion-level finding; Sonar S8997 (monkeypatch) rejection — I agreed with this in round 1 and the same reasoning holds.

SonarQube: Quality gate PASSED (all ratings A, 0% duplication, 0 security hotspots, analysis confirmed fresh against this head SHA via anonymous SonarCloud API). 6 new issues reported, all MAINTAINABILITY code smells, none gate-blocking:

  • 1 genuinely new regression from this round's fix commit, posted inline below (logger.py:190, python:S7504, unnecessary list()).
  • 5 are python:S8997 (the same "use monkeypatch" rule already discussed and rejected on thread 9) on new/pre-existing lines in test_logger.py (147, 242, 243, 279, and the carried-over 137) — not re-raised as new threads since the rejection rationale applies identically; noted in my reply to thread 9 for your awareness.

New findings: 1 Important, 4 Suggestion — all on code touched by this round's fix-up, anchored inline below. The Important finding is that the new concurrency regression test can't actually catch a regression of the very race it was added to guard against (verified empirically — see the inline comment). The four Suggestions are minor consistency/cleanup items in the chaining and restore logic, none of which are correctness bugs in the current code.

Strengths:

  • Thorough, well-targeted fix-up — every round-1 finding has a dedicated new regression test, not just a code change.
  • The _safe_repr() + outer try/except in _asyncio_exception_handler is exactly the right shape: the handler whose job is "never let a crash go unlogged" can no longer itself crash and lose the original traceback.
  • Pre-registering UNHANDLED_ERROR_SOURCES labels at import time (so increase() queries see the first real error) is a nice proactive touch addressing a cross-cutting concern from #1462, beyond what this round asked for.
  • ruff check/ruff format --check clean; full test file passes (27/27) at head.

🤖 Generated with Claude Code

Comment thread server/test/digi_server/test_logger.py Outdated
Comment thread server/digi_server/logger.py Outdated
Comment thread server/digi_server/logger.py Outdated
Comment thread server/digi_server/logger.py
Comment thread server/digi_server/logger.py
…ining

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
@Tim020

Tim020 commented Oct 22, 2026

Copy link
Copy Markdown
Contributor Author

Round 2 addressed in c6f4bac:

  • Race test rewritten to force the interleaving. Mutation check: replacing the lock with nullcontext() makes it fail; restored, it passes.
  • Dropped the list() over items().
  • Uninstall now only restores hooks that are still ours (new test).
  • Removed the redundant self-checks and fixed the _chain docstring.
  • KeyboardInterrupt/SystemExit in the loop handler now uses the previous handler when one exists (new test).
  • S8997 stays rejected.
    Local checks: pytest 1219 passed, ruff check and format clean.

@sonarqubecloud

Copy link
Copy Markdown

@Tim020 Tim020 left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review round 3

Head SHA reviewed: 5998f6a6ee4acd0923018ea9807b4e6a62c70e42 (incremental diff since round 2: 5dca16f8..5998f6a6, scoped to server/digi_server/logger.py and server/test/digi_server/test_logger.py — server/main.py is unchanged this round; the diff also carries in health.py/test_health.py/test_digi_server.py from a merge of the base branch feature/obs-health-check, which is out of scope for this PR's own diff per gh pr diff --name-only)

Verdict: Ready to merge. All outstanding findings from rounds 1 and 2 are now resolved; no new issues found.

Previous round follow-up: 5/5 round-2 findings verified fixed and resolved. I didn't just read the diff for the concurrency-test fix — I checked out this commit in an isolated worktree, swapped _hooks_lock for a no-op context manager to simulate the original regression, and ran test_concurrent_install_is_race_free 5 times: it failed consistently (5/5) exactly as the fix is meant to catch, and passes with the real lock in place. Details on each in the individual thread replies:

  • test_concurrent_install_is_race_free now genuinely forces the interleaving (Barrier + a slow __len__) instead of being a smoke test — confirmed empirically.
  • logger.py:190's unnecessary list() wrap removed (Sonar S7504).
  • uninstall_exception_hooks() now checks ownership before restoring sys/threading hooks, matching the loop-handler restore.
  • Redundant self-reference guards deleted and the _chain docstring corrected.
  • The asyncio KeyboardInterrupt/SystemExit branch now chains to previous like every other path.

Two round-1 Suggestion-level threads remain open from earlier rounds with no new activity (both previously accepted as "no code change needed" — the main.py startup-ordering note, and the Sonar S8997/monkeypatch rejection) — not re-raised.

SonarQube: Quality gate PASSED (all ratings A, 0% duplication, 0 security hotspots, 0 bugs, 0 vulnerabilities; analysis confirmed fresh against this head SHA — analyzed 2026-10-22T22:57:53Z, after the commit at 22:55:52Z). 9 open issues, all the same already-discussed python:S8997 ("use monkeypatch") rule on test_logger.py — 4 are new lines from this round's tests (140, 150, 245-246, 282-283, 311-312, 330 across both rounds), but it's the identical pattern already raised, rejected with a convincing rationale (this file's unittest.TestCase classes already snapshot/restore hooks in setUp/tearDown), and accepted by me in round 1 — not re-litigated.

New findings: None. I reviewed the full incremental diff (both files) and ran ruff check, ruff format --check, and the full test_logger.py suite (29/29 passed) at head; nothing new to report.

Strengths:

  • Round 2's fix-up addressed every single finding from round 1 with a dedicated regression test — this round did the same for round 2, closing the loop completely.
  • The concurrency test fix in particular shows real care: rather than just asserting an ownership invariant, it forces the actual race condition to manifest, and the fix was validated (by me) to actually fail without the lock.
  • Clean, minimal diff — no scope creep, no new abstractions beyond what the findings required.

🤖 Generated with Claude Code

@Tim020
Tim020 enabled stacked auto-merge (squash) October 22, 2026 23:10
@Tim020
Tim020 merged commit 61dcdcb into dev Oct 22, 2026
28 checks passed
@Tim020
Tim020 deleted the feature/obs-capture-stdlib-logs branch October 22, 2026 23:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

claude Issues created by Claude large-diff server Pull requests changing back end code

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant