Skip to content

fix(witan-code): report a failed bridge write instead of swallowing it - #288

Merged
blarghmatey merged 3 commits into
mainfrom
bridge-failure-reporting
Aug 25, 2026
Merged

fix(witan-code): report a failed bridge write instead of swallowing it#288
blarghmatey merged 3 commits into
mainfrom
bridge-failure-reporting

Conversation

@blarghmatey

Copy link
Copy Markdown
Member

What are the relevant tickets?

tk-ci-indexer-reports-errors-0-while-its-bridge-wri-3e2f7a (p1). Fallout from tk-production-code-bridge-graph-is-wedged-on-a-pend-8318a4 (p0), which is now cleared.

Description (What does it do?)

The production cross-repo bridge wedged on 2026-08-25 and nothing anywhere said so. Every CI cycle logged the failure, printed bindings=0 errors=0, exited 0, and raised no Sentry issue. The binding data was frozen from 04:01 UTC until the barrier cleared at ~19:10 — about 15 hours — and it surfaced only because someone went looking for an unrelated feature and hit the same barrier head-on.

Two independent reasons it was invisible. Both had to be fixed; either alone would have kept it silent.

1. The level was the mechanism

configure_sentry installs LoggingIntegration(event_level=ERROR) specifically so a call site needs no capture_exception. Its own docstring is explicit that the many exc_info=True calls at DEBUG/INFO/WARNING are "expected, already-handled failures … breadcrumbs, not Sentry issues".

So logging the bridge failure at warning was a declaration that a throwing bridge write is expected and handled. It is neither. It logs at error now, which is all Sentry needs.

Verified end to end rather than arguedsentry_sdk initialised with a recording transport, the real configure_logging pipeline, the same integration config:

events after logger.warning(): 0
events after logger.error()  : 1
  exception type  : RuntimeError
  level           : error

2. Sentry was never initialised on that path anyway

configure_observability() was called only by serve. The CI indexer runs witan code index, so it had no Sentry client at all — no amount of level correctness at the call site could have reported anything.

It now runs in the CLI's meta launcher, for every command. instrument=False keeps the OTel auto-instrumentors out of a short-lived CLI, and everything there no-ops without its env var, so a developer with no SENTRY_DSN pays nothing.

3. The summary line stops lying

The failure is counted (stats.errors) and flagged (stats.bridge_failed, rendered bridge=FAILED). bindings=0 previously meant both "nothing to write" and "the write threw", and that one line is the only thing most people read.

Deliberately still non-fatal. The per-repo index genuinely succeeds and is worth keeping. But "non-fatal" and "unreported" are different claims, and this only ever meant the first.

How can this be tested?

just test-all

2405 pass across the workspace (1 / 308 / 580 / 532 / 984). just check-versions, just check-core-floor and prek all clean — no floor bump needed, since no new witan_core symbol is imported.

The new tests were verified to fail against the old behaviour, not merely to pass against the new one — I reinstated the warning call and re-ran:

FAILED test_a_failing_bridge_write_is_counted_and_flagged - assert False is True
FAILED test_a_failing_bridge_write_logs_at_error_so_sentry_sees_it
  - AssertionError: logged at 'warning'; Sentry's event_level is ERROR, so anything below it…

The level assertion is deliberately explicit rather than incidental, because the level is the Sentry trigger and a future refactor lowering it would otherwise silently re-break this.

Additional Context

One witan-core fix this forced out, and it was a real latent bug rather than a test artifact. Adding configure_observability() to the launcher broke test_github_app.py — passing in isolation, failing in the full run. Cause: configure_logging built logging.StreamHandler(sys.stderr), capturing the stream object once per process. Anything rebinding sys.stderr afterwards (capsys, redirect_stderr, a CLI swapping the stream) left every later log line going somewhere nobody reads.

The module already documents this exact hazard for its unconfigured fallback and solves it there with _LateBoundStderr. The configured path had the same bug and kept it, because nothing configured logging early enough for it to show. Both paths late-bind now.

What this does not do: alerting on bindings=0 across a whole cycle, and root-causing the ~3-4 day recurrence of the wedge itself. Both are follow-ups on the p0 task. This change is what makes the next occurrence visible; it does not stop it happening.

blarghmatey and others added 2 commits August 25, 2026 15:37
The cross-repo bridge write on production wedged for ~15 hours today and
nothing anywhere said so. Every CI cycle logged the failure, printed
`bindings=0 errors=0`, exited 0, and raised no Sentry issue. It surfaced only
because someone went looking for an unrelated feature and hit the same barrier.

Two independent reasons it was invisible, both fixed here.

THE LEVEL WAS THE MECHANISM. configure_sentry installs
LoggingIntegration(event_level=ERROR) precisely so a call site needs no
capture_exception — its own docstring says the many exc_info=True calls at
DEBUG/INFO/WARNING are "expected, already-handled failures ... breadcrumbs, not
Sentry issues". So logging the bridge failure at warning was a declaration that
a throwing bridge write is expected and handled. It is neither. It logs at
error now, which is all Sentry needs. Proven end to end against a recording
transport rather than argued: warning produces 0 events, error produces 1
carrying the RuntimeError and its stack.

SENTRY WAS NEVER INITIALISED ON THAT PATH ANYWAY. configure_observability() was
called only by `serve`, and the CI indexer runs `witan code index` — so no
amount of level correctness at the call site could have reported anything. It
now runs in the CLI's meta launcher, for every command. instrument=False keeps
the OTel auto-instrumentors out of a short-lived CLI, and everything there
no-ops without its env var, so a developer with no SENTRY_DSN pays nothing.

The failure is also counted (stats.errors) and flagged (stats.bridge_failed,
rendered as `bridge=FAILED`). `bindings=0` meant both "nothing to write" and
"the write threw", and the summary line is the only thing most people read.

Not made fatal: the per-repo half genuinely succeeds and is worth keeping.
"Non-fatal" and "unreported" are different claims and this only ever meant the
first.

── one witan-core fix this forced out ──

Adding configure_observability() to the launcher broke test_github_app.py, and
the cause was a real latent bug rather than a test artifact: configure_logging
built its handler as StreamHandler(sys.stderr), capturing the stream object
once per process. The module already documents this exact hazard for its
unconfigured fallback and solves it there with _LateBoundStderr — the
configured path had the same bug and kept it, because nothing configured
logging early enough for it to show. Anything rebinding sys.stderr afterwards
(capsys, redirect_stderr, a CLI swapping the stream) left every later log line
going somewhere nobody reads. Now late-bound on both paths.

Tests assert the level explicitly, and were verified to FAIL against the old
behaviour ("logged at 'warning'; Sentry's event_level is ERROR") rather than
merely passing against the new one.

2405 tests pass across the workspace.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RH7kCwSp8TbKQLZ7kbVnY1
Copilot AI balanced review requested due to automatic review settings August 25, 2026 19:40

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Pull request overview

This PR aims to make cross-repository bridge-write failures observable without discarding successful per-repository indexing.

Changes:

  • Counts and logs bridge failures at error level.
  • Adds bridge=FAILED to CLI summaries.
  • Late-binds configured logging to current sys.stderr.

Reviewed changes

Copilot reviewed 6 out of 6 changed files in this pull request and generated 2 comments.

Show a summary per file
File Description
packages/witan-core/witan_core/observability/logging.py Late-binds stderr logging.
packages/witan-core/CHANGELOG.md Documents stderr fix.
mcp/servers/witan-code/witan_code/indexer.py Records and reports bridge failures.
mcp/servers/witan-code/witan_code/cli.py Displays bridge status and initializes observability.
mcp/servers/witan-code/tests/test_indexer.py Tests bridge failure reporting.
mcp/servers/witan-code/CHANGELOG.md Documents failure-reporting changes.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread mcp/servers/witan-code/witan_code/cli.py
Comment thread packages/witan-core/witan_core/observability/logging.py
Review catch on #288, and it invalidated the fix as shipped.

`witan code …` mounts witan_code's cyclopts App via
`app.command(_code_app, name="code")` — the App, not its meta launcher. So
dispatch runs through witan's own `_launcher` and witan-code's never executes.
The CI indexer runs `witan code index .` (docker/witan-ci-index.sh:197), which
means configuring observability only in witan-code's launcher covered the
standalone binary nobody deploys and missed the one command the incident
actually came from. The output-format forwarding right below the new call is
the tell: it exists precisely because witan-code's launcher, which sets that
itself, is bypassed.

Both launchers configure it now. Idempotent, and no-ops without the env vars.

Also adds the two regression tests review asked for, and both were verified to
FAIL against the code they guard rather than merely to pass against the fix:

  test_the_umbrella_launcher_configures_observability
      - "the umbrella launcher did not configure observability"
  test_the_configured_handler_follows_a_rebound_stderr
      - "the handler wrote to the stderr captured at configure time"

The second is the one review was right to insist on: the existing observability
tests configure logging AFTER capsys is already in place, so they pass against
the old StreamHandler(sys.stderr) too. Order is the whole test — configure
first, rebind second — and the order-dependent cross-test failure that first
surfaced this was never a stable guard.

One self-inflicted bug found while checking that: the new test module used
`pytest.importorskip` inside a `skipif` decorator, which is evaluated at
COLLECTION and skipped the entire module — silently taking the two umbrella
tests with it and reporting "1 skipped" as though it had run. Replaced with a
plain try/except guard.

2408 tests pass across the workspace.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RH7kCwSp8TbKQLZ7kbVnY1
@blarghmatey
blarghmatey merged commit b50de52 into main Aug 25, 2026
16 checks passed
@blarghmatey
blarghmatey deleted the bridge-failure-reporting branch August 25, 2026 20:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants