From 3d961fa0aaf576d74cc1fccffcb0a94eb7d75bb2 Mon Sep 17 00:00:00 2001 From: Brent Edwards Date: Thu, 26 Mar 2026 01:02:10 +0000 Subject: [PATCH] =?UTF-8?q?test:=20add=20TDD=20bug-capture=20test=20for=20?= =?UTF-8?q?#988=20=E2=80=94=20ReactiveEventBus.emit=20swallows=20exception?= =?UTF-8?q?s=20(#1106)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary Add a TDD bug-capture Behave scenario that proves bug #988 exists: `ReactiveEventBus.emit()` exception handler logs only `type(exc).__name__` (e.g., "ValueError") without the exception message (`str(exc)`) or traceback (`exc_info=True`). When a subscriber fails, the log contains zero diagnostic detail, making production debugging impossible. ## What was done - **Feature file**: `features/tdd_event_bus_exception_swallow.feature` — tagged `@tdd_expected_fail @tdd_bug @tdd_bug_988` - **Step definitions**: `features/steps/tdd_event_bus_exception_swallow_steps.py` — subscribes a handler that raises `ValueError("detailed error message for debugging")`, emits an event, captures the structlog warning via `structlog.testing.capture_logs()`, and asserts: 1. The exception message text appears in the log entry (scenario 1) 2. The `exc_info` key is present and truthy, confirming traceback logging (scenario 2) - **Changelog**: Updated `CHANGELOG.md` with the new entry ## How the test works 1. A `ReactiveEventBus` is created with a subscriber that raises `ValueError` with a distinctive message 2. An event is emitted, triggering the failing handler 3. The `emit()` exception handler catches the error and logs a warning via structlog 4. **Scenario 1** asserts the exception **message** (not just the type name) appears in the log entry 5. **Scenario 2** asserts the log entry includes **`exc_info`** (traceback), per bug #988's acceptance criteria requiring `exc_info=True` 6. Both assertions **FAIL** because the current code only logs `type(exc).__name__` — confirming the bug 7. The `@tdd_expected_fail` tag inverts these failures to CI passes ## Test verification - `nox -s unit_tests` ✅ passes (462 features, 12,232 scenarios passed, 0 failed) - Both underlying assertions correctly fail, proving the bug exists - Tag validation rules pass: `@tdd_bug_988` has corresponding `@tdd_bug`, and `@tdd_expected_fail` has both - `nox -s lint` ✅ passes - `nox -s typecheck` ✅ passes (0 errors on changed files) ## Review fixes applied - **C1 (Critical)**: Rebased onto latest `master` (`5f5ef891`) to eliminate unrelated `docs/timeline.md` regression that was overwriting Day 42 data with stale Day 39 content - **m1**: Added docstrings to all four step functions - **m2**: Renamed parameter `ctx` → `context` across all step functions to match project convention (97%+ of codebase uses `context`) - **m3**: Added second scenario "Bug #988 — emit() logs traceback via exc_info when handler raises" with new `step_then_log_contains_traceback` step that verifies the `exc_info=True` requirement from bug #988 acceptance criteria - **n1 (Informational)**: Feature-level tags are valid Gherkin; no change needed - **n2 (Informational)**: `# type: ignore[import-untyped]` on behave imports is the established project convention (106+ files); no change needed ## Robot test N/A — this is a purely unit-level concern (testing a single class's internal error handling, no external services or IPC involved). Closes #1093 Reviewed-on: https://git.cleverthis.com/cleveragents/cleveragents-core/pulls/1106 Reviewed-by: Jeffrey Phillips Freeman Co-authored-by: Brent Edwards Co-committed-by: Brent Edwards --- CHANGELOG.md | 8 ++ .../tdd_event_bus_exception_swallow_steps.py | 104 ++++++++++++++++++ .../tdd_event_bus_exception_swallow.feature | 29 +++++ 3 files changed, 141 insertions(+) create mode 100644 features/steps/tdd_event_bus_exception_swallow_steps.py create mode 100644 features/tdd_event_bus_exception_swallow.feature diff --git a/CHANGELOG.md b/CHANGELOG.md index 0fdf7bcc..113e1db0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,14 @@ ## Unreleased +- Added TDD bug-capture test for bug #988 — ReactiveEventBus.emit() swallows + exception details. Behave BDD scenario (`@tdd_bug @tdd_bug_988 + @tdd_expected_fail`) captures the missing exception message and traceback in + the emit() exception handler. The test subscribes a handler that raises + ValueError with a distinctive message and asserts the message appears in the + structlog warning log — which currently fails, confirming the bug. The + `@tdd_expected_fail` tag inverts this to a CI pass until the fix is merged. + (#1093) - Added TDD bug-capture E2E tests for bug #1028 — ACMS indexing pipeline not wired into CLI. Four Robot Framework E2E tests prove ContextTierService starts empty on every CLI invocation. Tests use ``@tdd_expected_fail`` until the bug diff --git a/features/steps/tdd_event_bus_exception_swallow_steps.py b/features/steps/tdd_event_bus_exception_swallow_steps.py new file mode 100644 index 00000000..96d49fe5 --- /dev/null +++ b/features/steps/tdd_event_bus_exception_swallow_steps.py @@ -0,0 +1,104 @@ +"""Step definitions for tdd_event_bus_exception_swallow.feature. + +This test captures bug #988: ReactiveEventBus.emit() swallows exception +details. The exception handler logs only ``type(exc).__name__`` and omits +``str(exc)`` and ``exc_info=True``, making production debugging impossible. + +The scenario is tagged ``@tdd_expected_fail`` so the underlying assertion +failure (confirming the bug exists) is inverted to a CI pass. Once the +fix for #988 is merged, remove the ``@tdd_expected_fail`` tag from the +feature file and this test will run normally as a regression guard. +""" + +from __future__ import annotations + +import structlog +from behave import given, then, when # type: ignore[import-untyped] +from behave.runner import Context # type: ignore[import-untyped] + +from cleveragents.infrastructure.events.models import DomainEvent +from cleveragents.infrastructure.events.reactive import ReactiveEventBus +from cleveragents.infrastructure.events.types import EventType + +# The distinctive error message that must appear in log output. +_ERROR_MESSAGE = "detailed error message for debugging" + + +def _failing_handler(event: DomainEvent) -> None: + """Subscriber that always raises, simulating a real handler failure.""" + raise ValueError(_ERROR_MESSAGE) + + +@given("a ReactiveEventBus with a handler that raises a ValueError") +def step_given_bus_with_failing_handler(context: Context) -> None: + """Create a ReactiveEventBus and subscribe a handler that always raises.""" + context.bus = ReactiveEventBus() + context.bus.subscribe(EventType.PLAN_CREATED, _failing_handler) + + +@when("I emit an event that triggers the failing handler") +def step_when_emit_event(context: Context) -> None: + """Emit a PLAN_CREATED event and capture structlog output.""" + with structlog.testing.capture_logs() as captured: + context.bus.emit(DomainEvent(event_type=EventType.PLAN_CREATED)) + context.captured_logs = captured + + +@then("the warning log should contain the exception message text") +def step_then_log_contains_exception_message(context: Context) -> None: + """Assert the exception message (``str(exc)``) appears in the log entry.""" + # Find the warning log entry from the emit() exception handler. + warning_logs = [ + entry + for entry in context.captured_logs + if entry.get("log_level") == "warning" + and entry.get("event") == "event_handler_failed" + ] + assert warning_logs, ( + f"Expected a 'event_handler_failed' warning log entry, " + f"but captured logs were: {context.captured_logs}" + ) + + log_entry = warning_logs[0] + + # The fix for #988 must include str(exc) in the log entry — either as + # a dedicated field (e.g. ``error_message``) or embedded in the event + # string. Assert that the distinctive error message text appears + # somewhere in the log entry's values. + log_values_str = " ".join(str(v) for v in log_entry.values()) + assert _ERROR_MESSAGE in log_values_str, ( + f"Bug #988: The exception message {_ERROR_MESSAGE!r} was not found " + f"in the warning log entry. The handler logged only the exception " + f"type name without the message. Log entry: {log_entry}" + ) + + +@then("the warning log should contain traceback information") +def step_then_log_contains_traceback(context: Context) -> None: + """Assert the log entry includes ``exc_info`` for full traceback output. + + Bug #988 acceptance criteria require ``exc_info=True`` so that the + traceback is available in production logs. When structlog captures logs, + the presence of an ``exc_info`` key (with a truthy value) confirms the + logger was invoked with traceback forwarding enabled. + """ + warning_logs = [ + entry + for entry in context.captured_logs + if entry.get("log_level") == "warning" + and entry.get("event") == "event_handler_failed" + ] + assert warning_logs, ( + f"Expected a 'event_handler_failed' warning log entry, " + f"but captured logs were: {context.captured_logs}" + ) + + log_entry = warning_logs[0] + + # structlog.testing.capture_logs() stores exc_info when the caller + # passes exc_info=True. Assert the key is present and truthy. + assert log_entry.get("exc_info"), ( + f"Bug #988: The warning log entry is missing 'exc_info' (traceback). " + f"The handler must call logger.warning(..., exc_info=True) so that " + f"the full traceback appears in production logs. Log entry: {log_entry}" + ) diff --git a/features/tdd_event_bus_exception_swallow.feature b/features/tdd_event_bus_exception_swallow.feature new file mode 100644 index 00000000..0768d91b --- /dev/null +++ b/features/tdd_event_bus_exception_swallow.feature @@ -0,0 +1,29 @@ +@tdd_expected_fail @tdd_bug @tdd_bug_988 +Feature: TDD Bug #988 — ReactiveEventBus.emit() swallows exception details + As a developer debugging a subscriber failure + I want the exception handler in ReactiveEventBus.emit() to log the full + exception message and traceback + So that I can diagnose why a subscriber failed without guessing + + This test captures bug #988. The exception handler in + ReactiveEventBus.emit() currently logs only `type(exc).__name__` + (e.g. "ValueError") without `str(exc)` or `exc_info=True`. When a + subscriber raises, the log contains no diagnostic detail — no message, + no traceback, no clue about which input or state caused the failure. + + The test uses `@tdd_expected_fail` because the underlying assertion + FAILS (confirming the bug exists). The tag inversion mechanism causes + CI to report the test as passed. Once the fix for #988 is merged, + the `@tdd_expected_fail` tag must be removed so the test runs normally. + + See CONTRIBUTING.md > Bug Fix Workflow > TDD Bug Test Tags. + + Scenario: Bug #988 — emit() logs exception message when handler raises + Given a ReactiveEventBus with a handler that raises a ValueError + When I emit an event that triggers the failing handler + Then the warning log should contain the exception message text + + Scenario: Bug #988 — emit() logs traceback via exc_info when handler raises + Given a ReactiveEventBus with a handler that raises a ValueError + When I emit an event that triggers the failing handler + Then the warning log should contain traceback information