diff --git a/CHANGELOG.md b/CHANGELOG.md index 0fdf7bcce..113e1db03 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 000000000..96d49fe58 --- /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 000000000..0768d91b6 --- /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