From eb9e8ba4fed664074f1563a171491f81418aad19 Mon Sep 17 00:00:00 2001 From: "Brent E. Edwards" Date: Sun, 22 Mar 2026 23:23:45 +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?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add a Behave BDD scenario that captures bug #988: ReactiveEventBus.emit() exception handler logs only type(exc).__name__ without str(exc) or exc_info=True, making production debugging of subscriber failures impossible. The test subscribes a handler that raises ValueError with a distinctive message, emits an event, captures the structlog warning via structlog.testing.capture_logs(), and asserts the exception message text appears in the log entry. The assertion fails (confirming the bug exists) and the @tdd_expected_fail tag inverts the result so CI passes. Files added: - features/tdd_event_bus_exception_swallow.feature — tagged with @tdd_expected_fail @tdd_bug @tdd_bug_988 - features/steps/tdd_event_bus_exception_swallow_steps.py — step definitions exercising the specific emit() exception-handling code path Robot test: N/A — purely unit-level concern (single class, no external services or IPC). ISSUES CLOSED: #1093 --- 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 8a0f04bfe..629df8129 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 BuiltinAdapter class and MCP automatic resource slot creation. BuiltinAdapter wraps register_file_tools/register_git_tools/register_subplan_tool into a unified adapter interface. McpAdapter.infer_resource_slots() analyzes 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 -- 2.52.0