fix(events): log full exception details in ReactiveEventBus.emit() error handlers
CI / build (pull_request) Successful in 21s
CI / helm (pull_request) Successful in 22s
CI / lint (pull_request) Successful in 3m19s
CI / quality (pull_request) Successful in 3m48s
CI / security (pull_request) Successful in 4m6s
CI / typecheck (pull_request) Successful in 4m17s
CI / integration_tests (pull_request) Successful in 6m50s
CI / unit_tests (pull_request) Successful in 7m19s
CI / docker (pull_request) Successful in 1m33s
CI / e2e_tests (pull_request) Successful in 11m31s
CI / coverage (pull_request) Successful in 11m49s
CI / status-check (pull_request) Successful in 1s
CI / benchmark-publish (pull_request) Has been skipped
CI / benchmark-regression (pull_request) Successful in 51m59s

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
This commit is contained in:
Luis Mendes
2026-03-28 00:52:54 +00:00
parent efacfd61c3
commit 240a741b2a
4 changed files with 84 additions and 18 deletions
+8
View File
@@ -2,6 +2,14 @@
## Unreleased
- Fixed `ReactiveEventBus.emit()` exception handlers to enable traceback
forwarding (`exc_info=True`). The per-handler exception block already
logged `error=str(exc)` and `error_type`, but omitted `exc_info=True`,
so no traceback was forwarded to the configured log output. The RxPY
stream error handler had the same omission. Both now include
`exc_info=True` so that structlog forwards the full traceback. Removed
`@tdd_expected_fail` tag from the TDD test so all three scenarios run as
normal regression guards. (#988)
- Implemented `--mount` flag on `resource add container-instance`. Supports
resource-reference mounts (`--mount local/api-repo:/workspace`) and
host-path mounts (`--mount /var/config:/config:ro`). Multiple `--mount`
@@ -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
@@ -102,3 +101,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}"
)
@@ -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.
@@ -24,8 +21,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
@@ -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(