From 1852fdf1b5649d4ef88d796cc4933813fa7aebf7 Mon Sep 17 00:00:00 2001 From: Tobias Macey Date: Tue, 25 Aug 2026 15:37:26 -0400 Subject: [PATCH 1/3] fix(witan-code): report a failed bridge write instead of swallowing it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Claude-Session: https://claude.ai/code/session_01RH7kCwSp8TbKQLZ7kbVnY1 --- mcp/servers/witan-code/tests/test_indexer.py | 94 +++++++++++++++++++ mcp/servers/witan-code/witan_code/cli.py | 21 +++++ mcp/servers/witan-code/witan_code/indexer.py | 26 ++++- .../witan_core/observability/logging.py | 14 ++- 4 files changed, 153 insertions(+), 2 deletions(-) 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/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( From 8ca3b44bb1d69d794af88169b0d47a20c100df3b Mon Sep 17 00:00:00 2001 From: Tobias Macey Date: Tue, 25 Aug 2026 15:38:05 -0400 Subject: [PATCH 2/3] docs: changelog entries for the bridge-failure reporting fix Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01RH7kCwSp8TbKQLZ7kbVnY1 --- mcp/servers/witan-code/CHANGELOG.md | 25 +++++++++++++++++++++++++ packages/witan-core/CHANGELOG.md | 16 ++++++++++++++++ 2 files changed, 41 insertions(+) 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/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 From 564496ba6c30ef488f7079771c30f90adc8b27d2 Mon Sep 17 00:00:00 2001 From: Tobias Macey Date: Tue, 25 Aug 2026 15:51:43 -0400 Subject: [PATCH 3/3] fix(witan): configure observability on the umbrella CLI path too MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Claude-Session: https://claude.ai/code/session_01RH7kCwSp8TbKQLZ7kbVnY1 --- mcp/servers/witan/CHANGELOG.md | 14 +++ .../witan/tests/test_cli_observability.py | 91 +++++++++++++++++++ mcp/servers/witan/witan/cli/__init__.py | 14 +++ .../witan-core/tests/test_observability.py | 43 +++++++++ 4 files changed, 162 insertions(+) create mode 100644 mcp/servers/witan/tests/test_cli_observability.py 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/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()