diff --git a/mcp/servers/witan-code/CHANGELOG.md b/mcp/servers/witan-code/CHANGELOG.md index deb01691..1be2fee4 100644 --- a/mcp/servers/witan-code/CHANGELOG.md +++ b/mcp/servers/witan-code/CHANGELOG.md @@ -10,6 +10,31 @@ a MINOR bump may include breaking changes). ### Fixed +- **A failed cross-repo bridge write is reported instead of swallowed.** The + production bridge wedged for ~15 hours on 2026-08-25 and nothing said so: + every CI cycle logged the failure, printed `bindings=0 errors=0`, exited 0, + and raised no Sentry issue. Two independent causes. + + The site logged at `warning`. `configure_sentry` installs + `LoggingIntegration(event_level=ERROR)` so a call site needs no + `capture_exception`, which makes the level the entire mechanism — and by that + contract a warning declares the failure "expected and already handled". A + throwing bridge write is neither. It logs at `error` now; verified end to end + against a recording transport (warning → 0 events, error → 1 issue with the + exception attached). + + Sentry was also never initialised on that path: `configure_observability()` + ran only in `serve`, and the CI indexer runs `witan code index`. It now runs + in the CLI's meta launcher for every command, with `instrument=False` to keep + the OTel auto-instrumentors out of a short-lived CLI. Everything there no-ops + without its env var, so a developer with no `SENTRY_DSN` pays nothing. + + The failure is now counted (`errors`) and flagged (`bridge=FAILED` in the + summary). `bindings=0` previously meant both "nothing to write" and "the + write threw". Deliberately still non-fatal — the per-repo index succeeds and + is worth keeping — but "non-fatal" and "unreported" are different claims. + + - **The test suite no longer asserts an environment.** Four tests (`test_branches.py`'s three branch-view assertions and `test_graph.py::test_a_shared_branch_view_needs_an_identity_to_own_it`) diff --git a/mcp/servers/witan-code/tests/test_indexer.py b/mcp/servers/witan-code/tests/test_indexer.py index bfc56062..c32eb43d 100644 --- a/mcp/servers/witan-code/tests/test_indexer.py +++ b/mcp/servers/witan-code/tests/test_indexer.py @@ -1,5 +1,7 @@ """End-to-end tests for the tree-sitter indexer and omnigraph store queries.""" +from pathlib import Path + from .conftest import requires_stack @@ -46,3 +48,95 @@ def test_incremental_reindex_skips_unchanged(sample_repo): second = indexer.index_path(sample_repo, config=cfg) assert second.indexed == 0 assert second.skipped >= 1 + + +# ── A failing bridge write must be reported, not swallowed ────────────────── +# +# It was swallowed, and that cost 15 hours of silently-frozen cross-repo +# bindings on production: every CI cycle logged a warning nothing read, +# reported `bindings=0 errors=0`, and exited 0. Sentry never saw it because its +# LoggingIntegration fires at ERROR and the site logged at WARNING — which by +# that integration's own contract declares a failure "expected and already +# handled". + + +def _failing_bridge(monkeypatch): + """Make the bridge write raise the way the production barrier did.""" + from witan_code import bridge as bridge_module + + def _raise(*args, **kwargs): + raise RuntimeError( + "omnigraph branch failed after 6 attempts — a recovery barrier on " + "the branch kept blocking the read" + ) + + monkeypatch.setattr(bridge_module, "write_bindings", _raise) + + +@requires_stack +def test_a_failing_bridge_write_is_counted_and_flagged(sample_repo, monkeypatch): + """`bindings=0` alone cannot distinguish "nothing to write" from "the write + threw", so the failure has to show up as both an error count and a flag.""" + from witan_code import config as cfg_mod + from witan_code import indexer + + _failing_bridge(monkeypatch) + + stats = indexer.index_path(sample_repo, config=cfg_mod.load()) + + assert stats.bridge_failed is True + assert stats.errors >= 1 + # Still not fatal: the per-repo half succeeded and is worth keeping. + assert stats.indexed >= 1 + assert stats.symbols >= 1 + + +@requires_stack +def test_a_failing_bridge_write_logs_at_error_so_sentry_sees_it( + sample_repo, monkeypatch +): + """THE level is the mechanism. + + `configure_sentry` installs `LoggingIntegration(event_level=ERROR)` so a + site like this needs no `capture_exception` call. That makes the level the + difference between a Sentry issue and a breadcrumb, which is why this + asserts it explicitly rather than trusting the call site to stay right. + """ + import structlog + + from witan_code import config as cfg_mod + from witan_code import indexer + + _failing_bridge(monkeypatch) + + with structlog.testing.capture_logs() as entries: + indexer.index_path(sample_repo, config=cfg_mod.load()) + + bridge = [e for e in entries if e.get("event") == "witan.code.index.bridge_failed"] + assert bridge, "the bridge failure was not logged at all" + assert bridge[0]["log_level"] == "error", ( + f"logged at {bridge[0]['log_level']!r}; Sentry's event_level is ERROR, " + "so anything below it is a breadcrumb and raises no issue" + ) + + +def test_the_summary_line_says_when_the_bridge_failed(): + """The one line anybody reads has to carry it.""" + from witan_code import cli, indexer + + printed: list[str] = [] + ok = indexer.IndexStats(scanned=1, indexed=1, bindings=0) + failed = indexer.IndexStats(scanned=1, indexed=1, bindings=0, bridge_failed=True) + + import builtins + + original = builtins.print + builtins.print = lambda *a, **k: printed.append(" ".join(str(x) for x in a)) + try: + cli._print_summary("index", Path("."), ok) + cli._print_summary("index", Path("."), failed) + finally: + builtins.print = original + + assert "bridge=FAILED" not in printed[0], "a clean run must not cry wolf" + assert "bridge=FAILED" in printed[1] diff --git a/mcp/servers/witan-code/witan_code/cli.py b/mcp/servers/witan-code/witan_code/cli.py index 3227b987..b804134c 100644 --- a/mcp/servers/witan-code/witan_code/cli.py +++ b/mcp/servers/witan-code/witan_code/cli.py @@ -763,6 +763,11 @@ def _print_summary(action: str, path: Path, stats: indexer.IndexStats) -> None: # Only when it happened: a purge is newsworthy (rows were deleted), # but printing purged=0 on every routine index is noise. + (f" purged={stats.purged}" if stats.purged else "") + # Same rule, opposite reason: `bindings=0` is unremarkable on a run + # with nothing to write and alarming on one whose bridge write threw, + # and the number alone cannot tell you which. Say so in the one line + # anybody reads. + + (" bridge=FAILED" if stats.bridge_failed else "") ) @@ -1028,6 +1033,22 @@ def _launcher( stitch. Values: txt | json | toml | yaml. Env: WITAN_OUTPUT_FORMAT. """ set_output_format(output_format) + # ★ EVERY command, not just `serve`. Until this was here, `serve` was the + # only entry point that configured observability — so the CI indexer, which + # runs `witan code index`, had no Sentry client at all and no amount of + # log-level correctness at a call site could have reported anything. + # + # It also puts structlog on the stdlib pipeline (`stdlib.LoggerFactory`), + # which is what Sentry's LoggingIntegration hooks; the unconfigured fallback + # writes straight to stderr and is invisible to it. + # + # `instrument=False` because this is a short-lived CLI: the OTel + # auto-instrumentors are worth their startup cost in a server process and + # not in `witan code repos`. Everything here no-ops without its env var — + # no SENTRY_DSN, no client — so a developer pays nothing. + from witan_core.observability import configure_observability + + configure_observability(instrument=False) app(tokens) diff --git a/mcp/servers/witan-code/witan_code/indexer.py b/mcp/servers/witan-code/witan_code/indexer.py index 34703f52..703dbc15 100644 --- a/mcp/servers/witan-code/witan_code/indexer.py +++ b/mcp/servers/witan-code/witan_code/indexer.py @@ -290,6 +290,13 @@ class IndexStats: edges: int = 0 bindings: int = 0 errors: int = 0 + bridge_failed: bool = False + """The cross-repo bridge write raised, so ``bindings`` is not a count. + + Without this, ``bindings=0`` means both "nothing to write" and "the write + threw", and the summary line is the only thing most people read. On + production those two states were indistinguishable for 15 hours. + """ purged: int = 0 """Files dropped from the store because they are no longer part of the repo — deleted, or newly excluded (a nested checkout, a skipped @@ -535,7 +542,24 @@ def index_path( indexed_files=frozenset(indexed_rel) if can_purge else None, ) except Exception as exc: # noqa: BLE001 — bridge is best-effort, never fatal - logger.warning( + # ERROR, not warning, and the level is the whole mechanism. Sentry's + # LoggingIntegration is installed with `event_level=ERROR` precisely so + # a site like this needs no `capture_exception` call — but that also + # means a warning here was, by that same contract, a declaration that + # the failure is "expected and already handled". A bridge write that + # throws is neither. + # + # It cost 15 hours of silently-frozen cross-repo bindings on production + # to find that out: every CI cycle logged this line, reported + # `bindings=0 errors=0`, exited 0, and raised nothing anywhere. See + # witan_core.observability.telemetry.configure_sentry. + # + # Still not fatal — the per-repo index above IS written and is worth + # keeping — but "non-fatal" and "unreported" are different claims, and + # this only ever meant the first. + stats.errors += 1 + stats.bridge_failed = True + logger.error( "witan.code.index.bridge_failed", repo=slug, error=str(exc), exc_info=True ) diff --git a/mcp/servers/witan/CHANGELOG.md b/mcp/servers/witan/CHANGELOG.md index 2cc9983f..40529759 100644 --- a/mcp/servers/witan/CHANGELOG.md +++ b/mcp/servers/witan/CHANGELOG.md @@ -8,6 +8,20 @@ a MINOR bump may include breaking changes). ## [Unreleased] +### Fixed + +- **The umbrella CLI configures observability, which is what actually covers + the CI indexer.** `witan code …` mounts witan_code's cyclopts App but not its + meta launcher, so `witan code index` — literally what + `docker/witan-ci-index.sh` runs — dispatches through `witan.cli._launcher` + and never executes witan-code's own. Configuring it only there (the first cut + of this fix) left the production path with no Sentry client and the incident + it was written for just as silent. The output-format forwarding a few lines + down is the tell: it exists because witan-code's launcher, which sets that + itself, is bypassed. Caught in review on #288. + +## [Unreleased] + ### Changed - **`import witan.server` needing the omnigraph binary is now a decision on diff --git a/mcp/servers/witan/tests/test_cli_observability.py b/mcp/servers/witan/tests/test_cli_observability.py new file mode 100644 index 00000000..ff79741b --- /dev/null +++ b/mcp/servers/witan/tests/test_cli_observability.py @@ -0,0 +1,91 @@ +"""Every CLI dispatch path must configure observability. + +Without this, a Sentry-worthy `log.error` at a call site reports nothing, +because no client was ever installed. That is half of why the production +cross-repo bridge failed silently for ~15 hours: the site logged at `warning` +AND the process it ran in had no Sentry client at all. + +★ THE PATH THAT MATTERS IS THE UMBRELLA ONE. `witan code …` mounts +witan_code's cyclopts App but NOT its meta launcher, so `witan code index` — +which is literally what `docker/witan-ci-index.sh` runs — dispatches through +`witan.cli._launcher` and never touches `witan_code.cli._launcher`. Fixing +only the latter looked right and covered nothing that was actually failing. +""" + +import pytest + + +def _stub_dispatch(monkeypatch, module): + """Replace the module's `app` so the launcher dispatches nowhere. + + The launcher resolves `app` as a global at call time, so rebinding the + name is enough — and it keeps the test off every real command's side + effects while still exercising the launcher body. + """ + dispatched: list[tuple] = [] + monkeypatch.setattr(module, "app", lambda tokens: dispatched.append(tokens)) + return dispatched + + +def _record_configure(monkeypatch): + calls: list[dict] = [] + import witan_core.observability as obs + + monkeypatch.setattr( + obs, "configure_observability", lambda **kw: calls.append(kw), raising=True + ) + return calls + + +def test_the_umbrella_launcher_configures_observability(monkeypatch): + """`witan …`, including the mounted `witan code index` the CI indexer runs.""" + from witan import cli + + calls = _record_configure(monkeypatch) + dispatched = _stub_dispatch(monkeypatch, cli) + + cli._launcher("code", "index", ".") + + assert calls, ( + "the umbrella launcher did not configure observability — `witan code " + "index` is the CI indexer's command, so nothing it logs would reach " + "Sentry" + ) + assert dispatched == [("code", "index", ".")] + + +def test_the_umbrella_launcher_skips_the_otel_instrumentors(monkeypatch): + """A short-lived CLI should not pay auto-instrumentation startup cost.""" + from witan import cli + + calls = _record_configure(monkeypatch) + _stub_dispatch(monkeypatch, cli) + + cli._launcher("whoami") + + assert calls[0].get("instrument") is False + + +# A plain guard, not `pytest.importorskip` in a decorator: that call is +# evaluated at COLLECTION and skips the whole module when it raises, which +# silently took the two umbrella tests above with it. +try: + import witan_code # noqa: F401 + + _HAS_WITAN_CODE = True +except ImportError: # pragma: no cover - witan-code is a normal dependency here + _HAS_WITAN_CODE = False + + +@pytest.mark.skipif(not _HAS_WITAN_CODE, reason="witan-code not installed") +def test_the_witan_code_launcher_configures_observability_too(monkeypatch): + """The standalone `witan-code …` binary is a real path as well.""" + from witan_code import cli as code_cli + + calls = _record_configure(monkeypatch) + dispatched = _stub_dispatch(monkeypatch, code_cli) + + code_cli._launcher("index", ".") + + assert calls + assert dispatched == [("index", ".")] diff --git a/mcp/servers/witan/witan/cli/__init__.py b/mcp/servers/witan/witan/cli/__init__.py index 87abd981..53c3c088 100644 --- a/mcp/servers/witan/witan/cli/__init__.py +++ b/mcp/servers/witan/witan/cli/__init__.py @@ -320,6 +320,20 @@ def _launcher( txt | json | toml | yaml. Env: WITAN_OUTPUT_FORMAT. """ set_output_format(output_format) + # ★ HERE TOO, AND THIS IS THE PATH THAT MATTERS. `witan code …` mounts + # witan_code's cyclopts App (`app.command(_code_app, name="code")`) but NOT + # its meta launcher, so dispatch runs through THIS function and witan-code's + # own launcher never executes. The output-format forwarding just below is + # the tell: it exists precisely because witan-code's launcher — which sets + # that itself — is bypassed. + # + # The CI indexer runs `witan code index .` (docker/witan-ci-index.sh), so + # configuring observability only in witan-code's launcher would have left + # the exact incident this change exists to surface just as silent. + # Idempotent, and no-ops without the env vars; see witan_code.cli._launcher. + from witan_core.observability import configure_observability + + configure_observability(instrument=False) try: from witan_code.output import set_output_format as set_code_output_format diff --git a/packages/witan-core/CHANGELOG.md b/packages/witan-core/CHANGELOG.md index f0af2258..48c184c1 100644 --- a/packages/witan-core/CHANGELOG.md +++ b/packages/witan-core/CHANGELOG.md @@ -6,6 +6,22 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/) (pre-1.0: a MINOR bump may include breaking changes). +## [Unreleased] + +### Fixed + +- **`configure_logging`'s handler no longer captures `sys.stderr` at call + time.** It built `logging.StreamHandler(sys.stderr)` once per process, so + anything that rebound `sys.stderr` afterwards — pytest's `capsys`, + `contextlib.redirect_stderr`, a CLI swapping the stream — left every + subsequent log line going to a stream nobody reads. The module already + documents this 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 surface. Adding + `configure_observability()` to witan-code's CLI launcher surfaced it: the + first test through the launcher pinned the handler to its own `capsys`, and a + later test asserting on stderr saw an empty string. Both paths late-bind now. + ## [0.32.1] - 2026-08-24 ### Changed diff --git a/packages/witan-core/tests/test_observability.py b/packages/witan-core/tests/test_observability.py index 7eba28dd..5be314f4 100644 --- a/packages/witan-core/tests/test_observability.py +++ b/packages/witan-core/tests/test_observability.py @@ -393,3 +393,46 @@ def test_sentry_breadcrumbs_include_debug_records(monkeypatch): get_logger("test").debug("a debug breadcrumb") breadcrumbs = list(sentry_sdk.get_isolation_scope()._breadcrumbs) assert any(b["message"].find("a debug breadcrumb") != -1 for b in breadcrumbs) + + +# ── The configured handler must late-bind sys.stderr ──────────────────────── + + +def test_the_configured_handler_follows_a_rebound_stderr(): + """`configure_logging` runs ONCE per process; sys.stderr moves afterwards. + + A `StreamHandler(sys.stderr)` captures the stream object at construction, + so anything that rebinds sys.stderr later — pytest's capsys, + `redirect_stderr`, a CLI swapping the stream — leaves every subsequent log + line going somewhere nobody reads. The module already solves this for its + UNCONFIGURED fallback with `_LateBoundStderr`; the configured path had the + same bug. + + ★ THE ORDER IS THE TEST. Configure FIRST, rebind SECOND — that is the only + ordering the old implementation fails. A test that rebinds first (which is + what capsys-based tests do implicitly) passes either way and guards + nothing. + """ + import io + from contextlib import redirect_stderr + + from witan_core.observability.logging import ( + configure_logging, + get_logger, + reset_logging, + ) + + reset_logging() + try: + configure_logging(log_format="json", level="INFO") + + replacement = io.StringIO() + with redirect_stderr(replacement): + get_logger("late-bind-probe").error("witan.test.late_bound") + + assert "witan.test.late_bound" in replacement.getvalue(), ( + "the handler wrote to the stderr captured at configure time, not " + "the one in effect at log time" + ) + finally: + reset_logging() diff --git a/packages/witan-core/witan_core/observability/logging.py b/packages/witan-core/witan_core/observability/logging.py index 05518ed5..0b6ac3cc 100644 --- a/packages/witan-core/witan_core/observability/logging.py +++ b/packages/witan-core/witan_core/observability/logging.py @@ -224,7 +224,19 @@ def configure_logging( foreign_pre_chain=shared, ) # See "STDOUT IS THE PROTOCOL" in the module docstring — stderr is explicit. - handler = logging.StreamHandler(sys.stderr) + # + # `_LateBoundStderr()` rather than `sys.stderr`, for the reason that class + # already documents: a StreamHandler captures the stream object at + # construction, and this runs ONCE per process. Anything that rebinds + # sys.stderr afterwards — pytest's capsys, contextlib.redirect_stderr, a + # CLI that swaps the stream — leaves every subsequent log line going to a + # stream nobody is reading. The fallback factory above was already fixed + # for exactly this; the configured path had the same bug and kept it, + # because nothing configured logging early enough for it to show. Adding + # `configure_observability()` to the witan-code CLI launcher made it show: + # the first test through the launcher pinned the handler to its own + # capsys, and a later test asserting on stderr saw an empty string. + handler = logging.StreamHandler(_LateBoundStderr()) # type: ignore[arg-type] handler.setFormatter(formatter) logging.config.dictConfig(