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.
This commit is contained in:
Cal Corum 2026-01-26 13:32:43 -06:00
parent 1fbd3d1cfa
commit 939ae421aa
3 changed files with 65 additions and 9 deletions

View File

@ -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.
---

View File

@ -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}")

View File

@ -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.