Skip to content

fix(dispatcher): restore dispatch.decision logging in CI#312

Merged
thinmintdev merged 1 commit into
mainfrom
fix/dispatcher-decision-logging
May 25, 2026
Merged

fix(dispatcher): restore dispatch.decision logging in CI#312
thinmintdev merged 1 commit into
mainfrom
fix/dispatcher-decision-logging

Conversation

@thinmintdev
Copy link
Copy Markdown
Contributor

/diagnose root cause

tests/dispatcher/test_router.py::test_decision_logging_runs_on_every_resolution failed only inside the full pytest suite (the target test passes in isolation, and so does the whole tests/dispatcher/ subtree). Test pollution. Captured-log output proved the production code DID emit dispatch.decision — but the test's _capture structlog processor never received it:

INFO     hal0-dispatch:router.py:778 {'event': 'dispatch.decision', ...}
AssertionError: assert 'dispatch.decision' in []

Bisection narrowed the polluting set to tests/memory/* + tests/omni_router/test_api_wiring.py. Cognee (imported transitively by the memory tests) calls structlog.configure(cache_logger_on_first_use=True) (see cognee/shared/logging_utils.py:435). With that flag set globally, the dispatcher's module-level log = structlog.get_logger("hal0-dispatch") proxy caches its .bind to Cognee's processor list on first use. A subsequent structlog.configure(processors=[_capture]) in the test does NOT retroactively rebind cached BoundLoggerLazyProxy instances, so log.info("dispatch.decision", …) keeps firing through Cognee's processors and _capture never sees the event.

Fix is in the test: pop the cached bind off the dispatcher's log proxy before exercising it (so the next .info() materializes a fresh BoundLogger bound to the _capture processor), then restore the cached bind in the finally block so subsequent tests see the same proxy state. Production code is unchanged — the dispatcher's logging is correct.

Offending commit

69418d7 feat(memory): ADR-0014 [memory.graph] schema + cognify gate + /api/memory routes (#257) (#287) — 2026-05-23. Introduced tests/memory/test_cognee_wrapper.py + tests/memory/test_graph_gate.py, which were the first tests in the suite to exercise Cognee initialization and therefore the first to set cache_logger_on_first_use=True globally.

The string dispatch.decision itself is unchanged since dc8891a feat: Phase 1 port (history verified via git log -S 'dispatch.decision'). No production regression.

Verification commands

From /tmp/hal0-dispatcher-fix on a fresh Python 3.11 venv (uv venv --python 3.11, uv pip install -e '.[dev]'):

  • python -m pytest tests/dispatcher/test_router.py -xvs — 13 passed
  • python -m pytest tests/dispatcher/ — 81 passed
  • python -m pytest tests/dispatcher/ tests/api/ -x — 408 passed, 3 skipped (broader smoke per brief)
  • python -m pytest tests/memory tests/omni_router/test_api_wiring.py tests/dispatcher/test_router.py::test_decision_logging_runs_on_every_resolution — 25 passed (exact polluting combo that previously failed)
  • python -m pytest — 1649 passed, 3 skipped (full suite; was 1648 passed + 1 failed before the fix)
  • ruff check src/hal0/dispatcher/ tests/dispatcher/ — All checks passed
  • ruff format --check src/hal0/dispatcher/ tests/dispatcher/ — 15 files already formatted

Diff

One file, 16 insertions, 1 deletion — tests/dispatcher/test_router.py only. No production code changed.

Coordination

Four sibling PRs were blocked on this failure (#306, #307, #308, #309). They should re-run CI once this lands; their changes don't touch the dispatcher or memory areas so a green base should clear their python (3.11) runs.

When tests/memory runs first, Cognee calls structlog.configure(
cache_logger_on_first_use=True), which causes the dispatcher's
module-level log proxy to cache its .bind() to Cognee's processor
list on first use. A later structlog.configure(processors=[_capture])
in this test does NOT retroactively rebind cached proxies, so
dispatch.decision events fire through the old processor chain and
the test's captured list stays empty. Drop the cached bind before
exercising the dispatcher and restore it after.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
@thinmintdev thinmintdev merged commit 4558137 into main May 25, 2026
4 checks passed
@thinmintdev thinmintdev deleted the fix/dispatcher-decision-logging branch May 25, 2026 18:08
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.

1 participant