From 939ae421aa008d1ae8c823805965ca4e93ba5fae Mon Sep 17 00:00:00 2001 From: Cal Corum Date: Mon, 26 Jan 2026 13:32:43 -0600 Subject: [PATCH] Add exception logging to effect registry (Issue #14) Effect handler exceptions now logged at ERROR level with full context: - effect_id, source_player_id, source/target card IDs, params - Full traceback via logger.exception() Game still returns safe EffectResult.failure() to prevent crashes, but debugging information is now preserved in logs. --- backend/SYSTEM_REVIEW.md | 20 ++++++---- backend/app/core/effects/registry.py | 16 +++++++- .../tests/core/test_effects/test_registry.py | 38 +++++++++++++++++++ 3 files changed, 65 insertions(+), 9 deletions(-) diff --git a/backend/SYSTEM_REVIEW.md b/backend/SYSTEM_REVIEW.md index c2e704b..0be9a31 100644 --- a/backend/SYSTEM_REVIEW.md +++ b/backend/SYSTEM_REVIEW.md @@ -227,17 +227,21 @@ Added 9 new tests covering: --- -### 14. Exception Swallowing Hides Errors -**File:** `app/core/effects/registry.py:97` +### 14. ~~Exception Swallowing Hides Errors~~ FIXED +**File:** `app/core/effects/registry.py:93-107` -```python -except Exception as e: - return EffectResult.failure(f"Effect '{effect_id}' failed: {e}") -``` +~~This catches all exceptions including programming errors, making debugging difficult.~~ -This catches all exceptions including programming errors, making debugging difficult. +**Resolution:** Added proper logging with `logger.exception()` which captures the full traceback at ERROR level. The log message now includes: +- The effect_id that failed +- Source player ID +- Source and target card IDs +- Effect parameters +- Full exception traceback -**Fix:** Log full traceback at ERROR level, or only catch expected exceptions. +The game still returns a safe `EffectResult.failure()` to prevent crashes, but debugging information is now preserved in the logs. + +Added 1 test verifying that exceptions are logged with full context and traceback. --- diff --git a/backend/app/core/effects/registry.py b/backend/app/core/effects/registry.py index 1102d62..4dc1950 100644 --- a/backend/app/core/effects/registry.py +++ b/backend/app/core/effects/registry.py @@ -22,10 +22,13 @@ the actual effect implementations, allowing cards to be defined in JSON/database while effect logic lives in Python. """ +import logging from collections.abc import Callable from app.core.effects.base import EffectContext, EffectResult +logger = logging.getLogger(__name__) + # Type alias for effect handler functions EffectHandler = Callable[[EffectContext], EffectResult] @@ -93,7 +96,18 @@ def resolve_effect(effect_id: str, ctx: EffectContext) -> EffectResult: try: return handler(ctx) except Exception as e: - # Catch any exceptions from handlers to prevent game crashes + # Log full traceback for debugging, but return safe failure result + # to prevent game crashes. This preserves the exception details + # while allowing the game to continue gracefully. + logger.exception( + "Effect handler '%s' raised an exception. Context: source_player=%s, " + "source_card=%s, target_card=%s, params=%s", + effect_id, + ctx.source_player_id, + ctx.source_card_id, + ctx.target_card_id, + ctx.params, + ) return EffectResult.failure(f"Effect '{effect_id}' failed: {e}") diff --git a/backend/tests/core/test_effects/test_registry.py b/backend/tests/core/test_effects/test_registry.py index b38cce8..04cdc66 100644 --- a/backend/tests/core/test_effects/test_registry.py +++ b/backend/tests/core/test_effects/test_registry.py @@ -233,6 +233,44 @@ class TestResolveEffect: assert "failed" in result.message assert "Intentional error" in result.message + def test_resolve_effect_logs_exceptions(self, caplog: pytest.LogCaptureFixture) -> None: + """ + Verify resolve_effect logs full exception details when handler fails. + + This ensures debugging information is preserved even though the game + continues gracefully. The log should include the effect_id, context + details, and the full traceback. + """ + import logging + + @effect_handler("logging_buggy_effect") + def buggy_handler(ctx: EffectContext) -> EffectResult: + raise ValueError("Detailed error message for logging test") + + ctx = make_test_context() + ctx.source_card_id = "test-source-card" + ctx.target_card_id = "test-target-card" + ctx.params = {"test_param": 123} + + with caplog.at_level(logging.ERROR): + result = resolve_effect("logging_buggy_effect", ctx) + + # Verify the result is still a failure + assert result.success is False + + # Verify the exception was logged with context + assert len(caplog.records) == 1 + log_record = caplog.records[0] + assert log_record.levelname == "ERROR" + assert "logging_buggy_effect" in log_record.message + assert "player1" in log_record.message # source_player_id + assert "test-source-card" in log_record.message + assert "test-target-card" in log_record.message + + # Verify traceback is included (logger.exception includes exc_info) + assert log_record.exc_info is not None + assert "Detailed error message for logging test" in str(log_record.exc_info[1]) + def test_resolve_effect_returns_handler_result(self) -> None: """ Verify resolve_effect returns the handler's result.