From d136e9103fcde51d5c3ebff020dbc4f348313723 Mon Sep 17 00:00:00 2001 From: Luis Mendes Date: Sat, 28 Mar 2026 00:52:54 +0000 Subject: [PATCH] fix(events): log full exception details in ReactiveEventBus.emit() error handlers Add exc_info=True to both _logger.warning() calls in ReactiveEventBus.emit(): the per-handler exception block ("event_handler_failed") and the RxPY stream error block ("reactive_stream_error"). Both handlers already logged error=str(exc) (the exception message text) and error_type, but omitted the traceback. With exc_info=True structlog now forwards the full traceback to the configured log output, giving developers the diagnostic detail needed to debug subscriber and stream failures in production. Remove the @tdd_expected_fail tag from the traceback scenario in features/tdd_event_bus_exception_swallow.feature so that all three TDD scenarios (#988) run as normal regression guards. Add a third scenario covering the RxPY stream error path (reactive_stream_error) to verify exc_info is forwarded when the Subject dispatch raises. Update the feature description and step-definition docstring to reflect the fixed state and full coverage of both error paths. Fix CHANGELOG entry to accurately describe the pre-existing state: str(exc) was already logged; only exc_info=True was missing. ISSUES CLOSED: #988 --- .../tdd_event_bus_exception_swallow_steps.py | 69 +++++++++++++++++-- .../tdd_event_bus_exception_swallow.feature | 23 ++++--- .../infrastructure/events/reactive.py | 2 + 3 files changed, 76 insertions(+), 18 deletions(-) diff --git a/features/steps/tdd_event_bus_exception_swallow_steps.py b/features/steps/tdd_event_bus_exception_swallow_steps.py index a984528ea..d19c8dcdd 100644 --- a/features/steps/tdd_event_bus_exception_swallow_steps.py +++ b/features/steps/tdd_event_bus_exception_swallow_steps.py @@ -1,13 +1,12 @@ """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. +Regression guard for bug #988: ReactiveEventBus.emit() previously omitted +``exc_info=True`` in both the per-handler exception block and the RxPY +stream error block, so no traceback was forwarded to the log output when +a subscriber or stream observer raised an exception. -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. +Bug #988 has been fixed. The ``@tdd_expected_fail`` tag has been removed +and all scenarios now run as normal regression guards. """ from __future__ import annotations @@ -142,3 +141,59 @@ def step_then_log_contains_traceback(context: Context) -> None: f"The handler must call logger.warning(..., exc_info=True) so that " f"the full traceback appears in production logs. Log entry: {log_entry}" ) + + +# -- Stream error path steps ----------------------------------------------- + +# Distinctive error for the RxPY stream observer failure. +_STREAM_ERROR_MESSAGE = "stream observer failure for debugging" + + +@given("a ReactiveEventBus with a stream observer that raises a RuntimeError") +def step_given_bus_with_failing_stream_observer(context: Context) -> None: + """Create a ReactiveEventBus and attach a stream observer that raises.""" + context.bus = ReactiveEventBus() + + def _failing_observer(event: DomainEvent) -> None: + raise RuntimeError(_STREAM_ERROR_MESSAGE) + + # Subscribe directly on the RxPY stream so that on_next raises inside + # the Subject dispatch, triggering the reactive_stream_error handler. + context.bus.stream.subscribe(on_next=_failing_observer) + + +@when("I emit an event that triggers the stream error") +def step_when_emit_stream_error(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 for the stream error should contain traceback information") +def step_then_stream_error_log_contains_traceback(context: Context) -> None: + """Assert the RxPY stream error log entry includes ``exc_info``. + + The ``reactive_stream_error`` handler in ``emit()`` must forward the + full traceback via ``exc_info=True`` so that RxPY stream failures are + diagnosable in production logs. + """ + warning_logs = [ + entry + for entry in context.captured_logs + if entry.get("log_level") == "warning" + and entry.get("event") == "reactive_stream_error" + ] + assert warning_logs, ( + f"Expected a 'reactive_stream_error' warning log entry, " + f"but captured logs were: {context.captured_logs}" + ) + + log_entry = warning_logs[0] + + assert log_entry.get("exc_info"), ( + f"Bug #988: The 'reactive_stream_error' warning log entry is missing " + f"'exc_info' (traceback). The handler must call " + f"logger.warning(..., exc_info=True) so that the full traceback " + f"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 index 72c8a3d80..90ef44c04 100644 --- a/features/tdd_event_bus_exception_swallow.feature +++ b/features/tdd_event_bus_exception_swallow.feature @@ -5,17 +5,14 @@ Feature: TDD Issue #988 — ReactiveEventBus.emit() swallows exception details 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. + This test was written as a TDD bug-capture for #988. Both exception + handlers in ReactiveEventBus.emit() — the per-handler block and the + RxPY stream error block — originally omitted `exc_info=True`, so no + traceback was forwarded to the log output when a subscriber or stream + observer raised an exception. - The traceback scenario uses `@tdd_expected_fail` because that - assertion still FAILS while the bug exists. The tag inversion - mechanism causes CI to report that scenario as passed. Once the - fix for #988 is merged, the `@tdd_expected_fail` tag must be - removed so both scenarios run normally. + Bug #988 has been fixed. The `@tdd_expected_fail` tag has been removed + and all scenarios now run as normal regression guards. See CONTRIBUTING.md > Bug Fix Workflow > TDD Issue Test Tags. @@ -25,8 +22,12 @@ Feature: TDD Issue #988 — ReactiveEventBus.emit() swallows exception details When I emit an event that triggers the failing handler Then the warning log should contain the exception message text - @tdd_expected_fail 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 + + Scenario: Bug #988 — emit() logs traceback via exc_info when RxPY stream errors + Given a ReactiveEventBus with a stream observer that raises a RuntimeError + When I emit an event that triggers the stream error + Then the warning log for the stream error should contain traceback information diff --git a/src/cleveragents/infrastructure/events/reactive.py b/src/cleveragents/infrastructure/events/reactive.py index 4161bf3b9..ba0d4b45d 100644 --- a/src/cleveragents/infrastructure/events/reactive.py +++ b/src/cleveragents/infrastructure/events/reactive.py @@ -120,6 +120,7 @@ class ReactiveEventBus: event_type=event.event_type.value, error_type=type(exc).__name__, error=str(exc), + exc_info=True, ) self._audit_log.append(event.model_copy(deep=True)) @@ -134,6 +135,7 @@ class ReactiveEventBus: handler=getattr(handler, "__qualname__", repr(handler)), error_type=type(exc).__name__, error=str(exc), + exc_info=True, ) def subscribe(