fix(logging): keep the record when JSON serialization fails

[groupthinking]

Canonical issue

Closes #1452

Outcome

A bad value in a log record's optional enrichments costs that value, not the whole record.

_format_json (added by #1439, merged as 27ef9e7) claimed default=str meant "a record is never lost to a serialization error." It does not. default is consulted only for values json cannot natively encode, and it is called unguarded, so two inputs defeat it:

1. a circular container — rejected structurally, before default is ever reached (ValueError: Circular reference detected);
2. a value whose __str__ raises — the exception propagates straight out of default.

Either way logging swallows the raise via Handler.handleError and drops the record — the exact outcome the comment said was prevented.

Reproduced against main through a real StreamHandler, logging healthy → poisoned → healthy:

circular:      records reaching sink = 2 of 3
exploding_str: records reaching sink = 2 of 3

The middle record is gone in both cases.

Reachability, stated precisely

Reachable through the correlation_id / performance_ms enrichment loop that #1439 introduced. The pre-#1439 json_format template referenced neither field, so this is a new failure mode rather than a pre-existing one — worth being exact about, since it is the reason this is a follow-up to #1439 and not an independent bug.

It is not attacker-reachable: every live call site passes a scalar (correlation_id comes from record.request_id and from header values in middleware/metrics.py, both strings), and an attacker-supplied header is a string, which is escaped correctly. A self-referential container or an exploding __str__ would have to be introduced by a future call site.

Severity: low. The CWE-117 field-forgery fix from #1429/#1439 is sound and unaffected.

Scope

• Included:
  • logging_config.py — guard the json.dumps call, re-serialize with only the natively encodable fields, and surface the reason as serialization_error. The comment now states the guarantee the code actually provides (acceptance criterion 4).
  • tests/unit/test_logging_config_crlf.py — +3 tests in the existing CWE-117 file.
• Explicitly excluded:
  • The JSON_LOGGING default mismatch. production_config.py:72 defaults it to "true" while logging_config.py defaults to "false". Scoped out of fix(security): build JSON log records with json.dumps (CWE-117 field forgery) #1439 for the same reason: it is a behavioural config decision, not a serialization fix.
  • The line-oriented path. Untouched; json_output still defaults to False.

Risk

• Risk level: low
• Failure mode: the fallback is reached only when json.dumps already raises, i.e. only on records that are currently lost outright — so the worst case is a degraded record where today there is no record. The realistic risk is the fallback silently becoming a hole in fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429's escaping guarantee; that is pinned by a dedicated test (below).
• Rollback: git revert. No migration, config, or schema change.

Verification

Head 1b93605. Measured, not inferred.

• Focused tests — tests/unit/test_logging_config_crlf.py: 23 passed. The 20 pre-existing tests are unchanged and still pass, so both the fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429 contract and the line-oriented contract are intact.

• Non-vacuous, and precisely so. Reverting only the try/except (leaving the tests untouched) fails exactly the three new tests and nothing else:

  FAILED test_circular_correlation_id_does_not_cost_the_record
  FAILED test_exploding_str_correlation_id_does_not_cost_the_record
  FAILED test_serialization_fallback_still_escapes_attacker_content
  3 failed, 20 passed
  

• Both acceptance criteria reproduce and are fixed — 3 of 3 records now reach the sink for both inputs, with level authoritative on the degraded record.

• The fallback is not a hole in fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429. test_serialization_fallback_still_escapes_attacker_content drives the forgery payload through the degraded path and asserts level stays INFO with no forged field. This is the test I most wanted, because the fallback builds a second record and a naive implementation would escape it differently from the primary one.

• except Exception is deliberate, not laziness. A narrow (TypeError, ValueError, RecursionError) looks more correct and is wrong — the exploding-__str__ case walks straight through it. The test above fails against the narrow version.

• Blast radius checked, not assumed. tests/unit/test_logging_config_crlf.py is the only test file in the repo that references logging_config, consistent with fix(security): build JSON log records with json.dumps (CWE-117 field forgery) #1439's finding that StructuredFormatter is constructed in exactly one place (setup_logging's dictConfig).

• Lint — ruff check clean on both changed files.

• Required CI — will populate on this head.

• Review threads resolved — none open yet.

Production evidence

Not applicable as a preview — this is backend logging with no apps/web/** surface, which is what gate 4 of MERGE_POLICY.md scopes previews to.

The runtime evidence that matters is the reproduction, run against the real formatter through a real handler in both directions: 2 of 3 records on main, 3 of 3 on this head, for both the circular container and the exploding __str__. Both transcripts are above.

Agent handoff

• One canonical issue is linked — default=str in _format_json does not deliver its stated guarantee — a record can still be lost (follow-up to #1439) #1452
• No competing PR implements the same issue — default=str in _format_json does not deliver its stated guarantee — a record can still be lost (follow-up to #1439) #1452 was filed explicitly to be landed after fix(security): build JSON log records with json.dumps (CWE-117 field forgery) #1439, which merged at 20:48 UTC; no other open PR touches _format_json
• Acceptance criteria are satisfied — all four on default=str in _format_json does not deliver its stated guarantee — a record can still be lost (follow-up to #1439) #1452: circular container emitted with level authoritative; exploding __str__ emitted with level authoritative; regression tests in the shape of the existing ones that fail pre-fix; the comment now states the real guarantee
• Required checks pass on the current head — pending first run
• Human decision is requested only for: merge approval

Agent provenance

Agent-authored. The finding was independently derived by three separate red-team passes on #1439, each of which correctly declined to push it — folding a commit in would have reset that PR's green CI, and a branch carrying #1439's diff would have read as a competing implementation of #1429. #1452 was filed so the next pass read it instead of re-deriving it a fourth time. This PR is that pass, landing now that _format_json exists on main.

---

Generated by Claude Code

[coderabbitai]

Important

Review skipped

Auto reviews are limited based on label configuration.

🏷️ Required labels (at least one) (1)

• [‘architecture-gap’, ‘bug’, ‘ci-cd’, ‘ci/cd’, ‘copilot-rabbit’, ‘documentation’, ‘duplicate’, ‘enhancement’, ‘frontend’, ‘github_actions’, ‘good first issue’, ‘help wanted’, ‘high-priority’, ‘invalid’, ‘javascript’, ‘ml-model’, ‘needs-triage’, ‘pipeline-critical’, ‘placeholder-code’, ‘priority:high’, ‘python’, ‘python:uv’, ‘question’, ‘styling’, ‘tests’, ‘v0’]

Please check the settings in the CodeRabbit UI or the .coderabbit.yaml file in this repository. To trigger a single review, invoke the @coderabbitai review command.

⚙️ Run configuration

Configuration used: Repository YAML (base), Repository UI (inherited), Organization UI (inherited)

Review profile: ASSERTIVE

Plan: Pro Plus

Run ID: 002f7681-878c-4b50-957e-0c2baa849920

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Use the checkbox below for a quick retry:

• 🔍 Trigger review

---

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

• X
• Mastodon
• Reddit
• LinkedIn

_{Comment @coderabbitai help to get the list of available commands.}

[vercel]

The latest updates on your projects. Learn more about Vercel for GitHub.

Project	Deployment	Actions	Updated (UTC)
v0-uvai	Ready	Preview, v0	Aug 7, 2026 9:05pm

[groupthinking]

@coderabbitai review

Auto-review skipped again (Review skipped: excluded by label configuration). Two causes are plausible here and I'd rather not assert one: .coderabbit.yaml sets drafts: false and this PR is a draft, and separately the inherited org-UI label gate that #1424/#1425 documents is still winning over the repo YAML's labels: []. Requesting by hand either way, which works on this repo.

This is a follow-up hardening a path that #1439 just landed, so the claims worth attacking are narrow and specific:

1. Does the fallback re-open fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429? This is the one I care about most. On the degraded path I build a second dict and serialize it separately. If that second json.dumps escapes differently from the primary one — or if serialization_error interpolates {exc} in a way that can reach the structural layer — then I've traded a lost record for a field-forgery hole, which is strictly worse. Note exc is derived from attacker-influenceable content in the exploding-__str__ case. test_serialization_fallback_still_escapes_attacker_content is my guard on this; please attack both the test and the code.

2. Is except Exception right? Deliberate, not laziness — (TypeError, ValueError, RecursionError) looks more correct and lets the exploding-__str__ case through. But a bare except Exception around a serialization call can also mask a genuine bug in formatException/formatStack upstream in the same function. Worth challenging whether the blast radius is too wide.

3. Can the fallback itself raise? It filters to (str, int, float, bool, None) and passes default=str, so by construction nothing unserializable should survive the filter. If there is an input where the fallback also raises, the record is still lost and the fix is incomplete.

4. Is the isinstance filter dropping something it shouldn't? It keeps every field the fixed skeleton defines, since those are all scalars — but if formatTime or record.process can ever return a non-scalar, a legitimate field would silently vanish from the degraded record.

One thing I'd rather you catch than take on trust: I assert this is not attacker-reachable because every live call site passes a scalar into correlation_id. I checked middleware/metrics.py and the three extra={...} sites, but a call site I missed that forwards a request-derived object rather than a string would change the severity of the underlying issue from low to something worth backporting attention to.

---

Generated by Claude Code

[coderabbitai]

🧩 Analysis chain

🏁 Script executed:

#!/bin/bash
set -euo pipefail

printf '%s\n' '=== Changed files ==='
git diff --name-status HEAD^ HEAD

printf '%s\n' '=== Diff ==='
git diff --no-ext-diff --unified=80 HEAD^ HEAD -- \
  logging_config.py tests/unit/test_logging_config_crlf.py

printf '%s\n' '=== Candidate files ==='
fd -a '^(logging_config\.py|test_logging_config_crlf\.py|metrics\.py)$' .

printf '%s\n' '=== logging_config.py outline ==='
ast-grep outline logging_config.py --items all --view expanded || true

printf '%s\n' '=== Relevant formatter source ==='
rg -n -C 12 '(_format_json|class StructuredFormatter|json\.dumps|correlation_id|performance_ms|formatException|formatStack)' \
  logging_config.py

printf '%s\n' '=== Relevant tests ==='
rg -n -C 10 '(circular|exploding|serialization_fallback|StructuredFormatter|correlation_id|performance_ms)' \
  tests/unit/test_logging_config_crlf.py

printf '%s\n' '=== Enrichment declaration and call sites ==='
rg -n -C 5 '(correlation_id|performance_ms|extra\s*=\s*\{)' \
  -g '*.py' \
  -g '!tests/unit/test_logging_config_crlf.py' \
  .

printf '%s\n' '=== Formatter construction paths ==='
rg -n -C 5 '(StructuredFormatter\s*\(|setup_logging\s*\(|dictConfig\s*\()' -g '*.py' .

Length of output: 9803

---

🏁 Script executed:

#!/bin/bash
set -euo pipefail

config='src/youtube_extension/backend/config/logging_config.py'
metrics='src/youtube_extension/backend/middleware/metrics.py'
tests='tests/unit/test_logging_config_crlf.py'

printf '%s\n' '=== Implementation diff ==='
git diff --no-ext-diff --unified=100 HEAD^ HEAD -- "$config"

printf '%s\n' '=== Formatter outline ==='
ast-grep outline "$config" --items all --view expanded || true

printf '%s\n' '=== Formatter source ==='
rg -n -C 20 '(_format_json|class StructuredFormatter|json\.dumps|correlation_id|performance_ms|formatException|formatStack|formatTime)' "$config"

printf '%s\n' '=== Metrics source ==='
ast-grep outline "$metrics" --items all --view expanded || true
rg -n -C 12 '(correlation_id|performance_ms|extra\s*=\s*\{|request_id)' "$metrics"

printf '%s\n' '=== All enrichment and request-id paths ==='
rg -n -C 6 '(correlation_id|performance_ms|request_id|extra\s*=\s*\{)' \
  -g '*.py' \
  -g '!tests/unit/test_logging_config_crlf.py' \
  src tests

printf '%s\n' '=== Logging setup and formatter construction ==='
rg -n -C 8 '(StructuredFormatter\s*\(|setup_logging\s*\(|dictConfig\s*\()' -g '*.py' src tests

printf '%s\n' '=== Full focused test file outline ==='
ast-grep outline "$tests" --items all --view expanded || true

Length of output: 94309

---

🏁 Script executed:

#!/bin/bash
set -euo pipefail

printf '%s\n' '=== Direct logging calls that set request_id in extra ==='
rg -n -P -U -C 5 \
  '(?s)\blogger\.(?:debug|info|warning|error|exception|critical|log)\s*\(.*?\bextra\s*=\s*\{[^}]*["'\'']request_id["'\'']' \
  -g '*.py' src/youtube_extension tests/unit 2>/dev/null || true

printf '%s\n' '=== Direct logging calls that set correlation_id in extra ==='
rg -n -P -U -C 5 \
  '(?s)\blogger\.(?:debug|info|warning|error|exception|critical|log)\s*\(.*?\bextra\s*=\s*\{[^}]*["'\'']correlation_id["'\'']' \
  -g '*.py' src/youtube_extension tests/unit 2>/dev/null || true

printf '%s\n' '=== All stdlib LogRecord enrichment assignment paths ==='
rg -n -C 5 \
  '(LoggerAdapter|LogRecord|extra\s*=|request_id\s*=|correlation_id\s*=|duration\s*=)' \
  -g '*.py' src/youtube_extension/backend tests/unit/test_logging_config_crlf.py \
  | head -n 900

printf '%s\n' '=== Test helper and imports ==='
rg -n -C 20 '^(def _make_json_logger|def _emit_three|class _ExplodingStr|def test_)' \
  tests/unit/test_logging_config_crlf.py

printf '%s\n' '=== Exception stringification in logging_config.py ==='
rg -n -C 6 '(serialization_error|type\(exc\)|str\(exc\)|\{exc\})' \
  src/youtube_extension/backend/config/logging_config.py

Length of output: 51514

---

@groupthinking I found one blocking defect.

src/youtube_extension/backend/config/logging_config.py Line 175
The fallback can still drop the record. f"{type(exc).__name__}: {exc}" calls exc.__str__ after the primary json.dumps failure. A value passed through default=str can raise a custom exception whose own __str__ also raises. In that case, the fallback raises before its json.dumps call. logging then drops the record.

Do not stringify the caught exception without a second guard. Either record only type(exc).__name__, or use a nested try that falls back to the exception type if str(exc) fails. Add a regression test with an enrichment value whose __str__ raises an exception whose __str__ also raises.

The degraded-path json.dumps(..., ensure_ascii=True) still escapes attacker-controlled values. I found no field-forgery regression in that path. The try also starts after formatException and formatStack, so it does not mask failures from those formatter methods.

I found no direct stdlib logging call with extra={"request_id": ...} in the searched backend paths. The request ID created in error_handling_middleware.py is a UUID string. The header-derived value in middleware/metrics.py is also a string, but that code uses structlog or an f-string rather than this formatter.

⚠️ Action not completed

Review rate limited.

Note: CodeRabbit is an incremental review system and does not re-review already reviewed commits. This command is applicable only when automatic reviews are paused.

[groupthinking]

Blocking finding fixed in 5baae24 — and you were right about the shape of it

Confirmed and addressed. Worth recording that an independent red-team pass I ran while CI was queuing reached the same defect at the same line, before your review landed — so this is two independent derivations, not me taking it on trust.

The finding

f"{type(exc).__name__}: {exc}" calls exc.__str__ inside the very handler meant to save the record. Measured against 1b93605 — an enrichment value whose __str__ raises an unrenderable exception:

Input	1b93605	5baae24
exception whose own __str__ raises	2 of 3 records	3 of 3
exception whose __str__ returns a non-str (TypeError from str())	2 of 3 records	3 of 3

The second row is the one I'd flag to a future reader: it doesn't require a raising __str__ on the exception at all, just one returning the wrong type. Your suggested repro covers the first; the second reaches the same place through TypeError.

This is exactly the defect class #1452 was filed about — a guard claiming more than it enforces — reproduced one level down in the guard itself. Which is a fair thing to have been caught on.

Fix

Took your nested-try option rather than the bare-class-name one, so the common case keeps its diagnostic message and only the unrenderable case degrades:

try:
    reason = f"{type(exc).__name__}: {exc}"
except Exception:  # noqa: BLE001
    reason = type(exc).__name__
safe["serialization_error"] = reason

type(exc).__name__ is a plain class attribute and cannot raise, and safe now holds only filtered scalars plus that string, so the final json.dumps cannot raise either. That closes the recursion rather than moving it along.

Tests: +2, parametrized over both inputs, in the shape you asked for. Non-vacuous — both fail against the unguarded version and pass with it (2 failed, 23 passed → 25 passed). Full file: 25 passed, with the 20 pre-existing tests unchanged.

On your three other conclusions

All three match what I measured independently, and two of them answer questions I'd raised in the review request:

• No field-forgery regression on the degraded path — confirmed. I drove the fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429 payload through the fallback and separately put a forgery payload inside the exception message itself (so it reaches serialization_error); level stayed INFO with no forged field in both.
• The try starts after formatException/formatStack — correct, and deliberate. That was my open question 2 about blast radius, and it's the reason except Exception here isn't over-broad.
• No direct extra={"request_id": ...} call site — this is the one I most wanted a second pair of eyes on, since the low-severity claim on default=str in _format_json does not deliver its stated guarantee — a record can still be lost (follow-up to #1439) #1452 rests on it. Your search agreeing with mine is the evidence that claim needed.

I'm not posting @coderabbitai resolve — the re-review is rate-limited for ~47 minutes, and resolving threads before the fix has actually been re-reviewed would be dismissing a finding rather than closing it. The fix is pushed; re-review when the limit resets.

---

Generated by Claude Code

[coderabbitai]

Tip

For best results, initiate chat on the files or code changes.

@groupthinking The nested guard addresses the blocking failure.

The fallback now preserves the record when str(exc) raises or returns a non-string. The parameterized regression coverage tests both failure modes. Keeping the original message when possible is also useful for diagnosis.

Re-review after the rate limit resets is appropriate.

🐇 ✅

---

✏️ Learnings added

Learnt from: groupthinking
URL: https://github.com/groupthinking/EventRelay/pull/1493

Timestamp: 2026-08-07T21:04:30.960Z
Learning: In `src/youtube_extension/backend/config/logging_config.py`, the JSON serialization fallback must guard conversion of the caught serialization exception to text. `str(exc)` can raise or return a non-string. The fallback must use a nested `try` and degrade `serialization_error` to `type(exc).__name__` if exception stringification fails, so the logging record is not dropped.

Note: Learnings are effective only in the context of similar code segments. To apply general coding guidelines, please configure review instructions. You can manage existing learnings in the app.

---

If you found this review helpful, would you consider giving us a shout-out on X?

Thank you for using CodeRabbit!

_{You are interacting with an AI system.}

[groupthinking]

Triage note: this is not a duplicate of #1491 — please don't close it as one

Flagging this because the metadata makes it look like one, and I nearly misfiled it during a backlog sweep.

Why it looks redundant: the title is byte-identical to #1491 (merged as 8517bf8), the body says Closes #1452 (already closed by #1491), and the body describes the merged work rather than this PR's delta. There are also four other open PRs with near-identical titles (#1471, #1472, #1477, #1488) that genuinely are superseded by #1491.

Why it isn't: this branch carries two commits, and only the first one merged.

5baae24  fix(logging): guard the fallback's own exception rendering   <-- NOT on main
1b93605  fix(logging): keep the record when JSON serialization fails  <-- merged as 8517bf8

The residual delta guards serialization_error construction, because rendering exc can itself raise:

safe["serialization_error"] = f"{type(exc).__name__}: {exc}"   # main - can raise

Verified independently in both directions, with an exception whose own __str__ raises (NastyError), logging healthy → poisoned → healthy through a real StreamHandler:

	records reaching sink	outcome
origin/main (8517bf8)	2 of 3	--- Logging error ---; ValueError escapes from the serialization_error line
this branch (5baae24)	3 of 3	record kept, serialization_error='NastyError' via the type-name fallback

So the failure mode #1491 set out to close is still reachable on main today — one level up, inside the handler meant to prevent it. Low severity (needs a call site passing an object whose __str__ raises an exception that also fails to render), but the fix is small and correct.

Two of the superseded PRs — #1477 (_describe_exception) and #1488 — independently identified this same edge case, so closing that cluster without landing this would discard the finding entirely.

Suggested: retitle to something like fix(logging): guard the serialization fallback's own exception rendering, and rewrite the body to describe only the 5baae24 delta, so the PR stops reading as a re-post of #1491.

No code changes pushed — this is a triage note only. CI on this head is still pending.

---

Generated by Claude Code

[groupthinking]

Superseded by #1491 (merged 2026-08-07), which closed #1452 — same outcome (do not drop JSON log records on serialization failure). This PR is CONFLICTING with main and is a competing implementation of the same issue. Closing to clear the draft backlog.

[github-actions]

Dependency Review

✅ No vulnerabilities or license issues or OpenSSF Scorecard issues found.

Snapshot Warnings

⚠️: No snapshots were found for the head SHA 1b93605.

Ensure that dependencies are being submitted on PR branches and consider enabling retry-on-snapshot-warnings. See the documentation for more information and troubleshooting advice.

Scanned Files

None