test: add TDD bug-capture test for #988 — ReactiveEventBus.emit swallows exceptions (#1106)
CI / build (push) Successful in 23s
CI / lint (push) Successful in 3m20s
CI / typecheck (push) Successful in 3m50s
CI / security (push) Successful in 4m0s
CI / quality (push) Successful in 4m18s
CI / integration_tests (push) Successful in 9m19s
CI / unit_tests (push) Successful in 9m46s
CI / e2e_tests (push) Successful in 10m27s
CI / docker (push) Successful in 1m9s
CI / coverage (push) Successful in 12m2s
CI / status-check (push) Successful in 1s
CI / benchmark-regression (push) Has been skipped
CI / benchmark-publish (push) Successful in 30m22s
CI / build (push) Successful in 23s
CI / lint (push) Successful in 3m20s
CI / typecheck (push) Successful in 3m50s
CI / security (push) Successful in 4m0s
CI / quality (push) Successful in 4m18s
CI / integration_tests (push) Successful in 9m19s
CI / unit_tests (push) Successful in 9m46s
CI / e2e_tests (push) Successful in 10m27s
CI / docker (push) Successful in 1m9s
CI / coverage (push) Successful in 12m2s
CI / status-check (push) Successful in 1s
CI / benchmark-regression (push) Has been skipped
CI / benchmark-publish (push) Successful in 30m22s
## 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: #1106 Reviewed-by: Jeffrey Phillips Freeman <jeffrey.freeman@cleverthis.com> Co-authored-by: Brent Edwards <brent.edwards@cleverthis.com> Co-committed-by: Brent Edwards <brent.edwards@cleverthis.com>
This commit was merged in pull request #1106.
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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}"
|
||||
)
|
||||
@@ -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
|
||||
Reference in New Issue
Block a user