Log ownership: a raising frame must not log the traceback
- 主要語言
- Python
- 星號
- 4
- 分支
- 0
- 平均合併
- 1 天 5 小時
- 30 天內合併 PR
- 8
描述
### Description of Technical Debt
ADR-002 states the invariant an `ERROR` alarm depends on: among records emitted during a single invocation, the count of `ERROR` records equals the count of 5xx responses the service built to report a failed request.
Three sites break it today, each the same way — a frame logs at `ERROR` and then lets the exception escape to a frame that logs it again:
| Site | Today | Effect |
|---|---|---|
| `src/writers/writer_kafka.py`, `writer_postgres.py`, `writer_eventbridge.py` | `ERROR` before `raise WriteError` | Writer `ERROR` + `_write_to_all()` `WARNING` + aggregate `ERROR` = two `ERROR` records for one failed write, and on exception paths the same traceback twice |
| `src/handlers/handler_topic.py`, missing access config | `ERROR` before `raise RuntimeError` | Handler `ERROR` + boundary `logger.exception` = two `ERROR` for one 500 |
| `src/handlers/handler_token.py`, `with_public_keys_queried()` | `logger.exception` before `raise RuntimeError` | `_refresh_keys_if_needed()` catches it at `WARNING` and the request still succeeds: one `ERROR`, zero 5xx |
### Impact of Technical Debt
- An alarm on `level = "ERROR"` counts log lines, not failed requests. One failed Postgres write reads as two failures, so any future alerting or EMF metric built on the ERROR count is inflated from day one.
- The `handler_token` case is the inverse and worse: a token refresh that fails but recovers emits an `ERROR` on a request that returns 2xx, so the ERROR count also has false entries unrelated to any failure.
- The same traceback is written two or three times per failed write, inflating CloudWatch cost on exactly the requests that are already the most expensive to log.
- ADR-002 documents the invariant as the contract. Until these are fixed, the code and the ADR disagree, which is a trap for the next person wiring up monitoring.
### Category
Code Quality / Refactoring
### Priority
Medium - Should be addressed soon
### Proposed Solution
The fix is ownership, not level. Downgrading the writers to `WARNING` is **not** enough: `_write_to_all()` already emits a `WARNING` carrying the same traceback, so the duplicate simply moves one level down.
Apply the rule ADR-002 §Attaching tracebacks states:
> A traceback is logged exactly once, by the frame that converts the exception into a response or swallows it. A frame that wraps and re-raises does not log it above `DEBUG`.
Concretely:
1. **Writers** — drop the `ERROR` before `raise WriteError`. Use `raise WriteError(...) from exc` so `exc_info=True` on the caller's `WARNING` formats the full `__cause__` chain; nothing is lost. A `DEBUG` breadcrumb is acceptable where the writer knows something the caller does not.
2. **`handler_topic`, missing access config** — drop the `logger.error`; the boundary `logger.exception` in `dispatch_request()` already owns that record.
3. **`handler_token.with_public_keys_queried()`** — drop the `logger.exception` entirely. The function cannot know whether its caller treats the failure as fatal (initialization) or recoverable (refresh), so the decision belongs to the callers: the init path logs `ERROR`, `_refresh_keys_if_needed()` keeps its existing `WARNING`.
### Effort Estimate
1 day, including test updates
### Dependencies / Related
- ADR-002 §Logging strategy and §Attaching tracebacks (`adr/002-observability/002-observability.md`)
- #193
- PR #204
- #220 — the other invariant gap found in the same review
### Additional Context
Acceptance:
- A failed write emits exactly one `ERROR` (the aggregate) and one `WARNING` per failing writer.
- A 500 from missing access configuration emits exactly one `ERROR`.
- A failed token refresh that still returns 2xx emits no `ERROR`.
- Unit tests assert the record counts per level, not just the messages, so a regression fails the build rather than quietly re-inflating the count.
貢獻指南
這個儲存庫沒有索引到貢獻指南
評估
這個 Issue 還沒有評估資料。