fix(logging): keep the record when a JSON enrichment cannot serialize

[groupthinking]

Canonical issue

Closes #1452

Outcome

A log record is no longer lost when an optional JSON enrichment cannot be serialized. It is emitted with level authoritative and a serialization_error field naming what failed.

_format_json arrived in #1439 with this comment on its return:

# `default=str` keeps a non-serializable `extra` value from raising
# inside the logging path, where an exception would be swallowed and
# the record lost entirely.
return json.dumps(payload, ensure_ascii=True, default=str)

That claim is false. default is consulted only for values json cannot natively encode, and it is called unguarded, so two inputs still raise out of json.dumps inside Handler.emit — where logging swallows the exception via handleError and drops the record:

• a circular container — json.dumps rejects it structurally, before default is ever reached;
• a value whose __str__ raises — default is consulted, and the exception propagates straight back out of it.

Reproduced against main (a79f866) before changing anything — three logger.info calls through a real StreamHandler, the middle one poisoned:

circular         : 2 of 3 records reached the sink
exploding __str__: 2 of 3 records reached the sink

Same reproduction on this head:

circular         : 3 of 3 reached the sink | level=INFO | ValueError: Circular reference detected
exploding__str__ : 3 of 3 reached the sink | level=INFO | RuntimeError: str() exploded

Reachability

Via extra={"request_id": ...}, which populates correlation_id, and which middleware may set to a framework object rather than a string. Only the optional enrichments (performance_ms, correlation_id) can carry such a value — every other field in the payload is already a scalar.

Not reachable from request content, and not a vulnerability: an attacker-supplied header is a string, and strings were already escaped correctly. This is a robustness gap plus a comment that claimed more than the code enforced.

Scope

• Included:
  • logging_config.py — a fallback around the json.dumps call that keeps every JSON-native scalar, drops the unserializable enrichment, and reports the cause; a new _describe_exception helper; and the comment rewritten to state the guarantee the code actually provides.
  • tests/unit/test_logging_config_crlf.py — +5 tests in the existing CWE-117 file.
• Explicitly excluded:
  • The CWE-117 field-forgery fix itself. Untouched. The happy path is byte-identical; the fallback only runs where the old code raised.
  • The line-oriented path. Untouched — sanitize_log_record and the json_output=False branch are unchanged.
  • fix(security): build JSON log records with json.dumps (CWE-117 field forgery) #1439's Risk section, which repeats the same false claim. That PR is merged and its body is now a historical record; the live artifact is the code comment, and that is corrected here.
  • The JSON_LOGGING default mismatch (production_config.py:72 vs logging_config.py) — still open, still a separate behavioural decision.

Risk

• Risk level: low
• Failure mode: the fallback is on an error path that previously raised, so it cannot regress a record that serialized before. The realistic risk is the opposite one — the fallback masking a serialization bug that should be visible. It does not: serialization_error carries the exception type and message into the record itself, which is strictly more visible than the handleError stderr noise it replaces. The second json.dumps cannot raise, because every value it receives has been filtered to a JSON-native scalar.
• Rollback: git revert. No migration, config, or schema change. The emitted field set is unchanged for every record that serialized successfully before.

Verification

Head 90a013a. Measured, not inferred.

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

• Non-vacuous, and precisely so. Removing only the fallback block — leaving the tests and the new helper in place — fails exactly the three tests that cover it, and nothing else:

  FAILED test_unserializable_enrichment_does_not_cost_the_record[circular-poison0]
  FAILED test_unserializable_enrichment_does_not_cost_the_record[exploding-str-poison1]
  FAILED test_serialization_fallback_keeps_the_record_a_single_json_line
  3 failed, 22 passed
  

  The other two new tests correctly do not depend on the fallback: one asserts a benign scalar enrichment still takes the normal path, the other tests _describe_exception directly.

• The fallback honours the same guarantees as the happy path. A record that hits it with the fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429 forgery payload in the message still renders as one physical line, still parses, still has level == "INFO", and still has no forged field.

• Benign records are unaffected. extra={"request_id": "req-123"} still lands as correlation_id through the normal path, with no serialization_error field — so the fallback does not fire on serializable values.

• except Exception, deliberately, not a narrow tuple. (TypeError, ValueError, RecursionError) reads as more correct and is not: the exploding-__str__ case raises RuntimeError and walks straight through it. Noted at the call site so it does not get "tidied" later.

• Describing the caught exception is itself guarded. It can originate in a call site's own __str__, so its class may be one whose __str__ raises too — which would re-raise inside the handler and lose the record a second time. _describe_exception falls back to the type name, a plain attribute lookup. Covered by its own test.

• Blast radius checked, not assumed. _format_json is called from exactly one place (StructuredFormatter.format), and tests/unit/test_logging_config_crlf.py is the only test file in the repo that references the module.

• Lint — ruff 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 StreamHandler in both directions — 2 of 3 records on main, 3 of 3 on this head, for both inputs. Both transcripts are above. production_config.py:72 defaults JSON_LOGGING to "true", so the JSON path is the live one.

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 precisely so this would not be re-derived a fourth time, and it is explicit that the fix lands after fix(security): build JSON log records with json.dumps (CWE-117 field forgery) #1439 (merged as 715cbf52d) rather than alongside it. 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: a circular container and an exploding __str__ are both still emitted with level authoritative; a regression test in the shape of the existing ones covers both and fails on the pre-fix implementation; and the _format_json comment now states the guarantee the code actually provides, including why default=str alone is not it.
• Required checks pass on the current head — pending first run
• Human decision is requested only for: merge approval

Agent provenance

Agent-authored, under the PR remediation runbook. Found by three independent red-team passes on #1439, each of which derived it and declined to push — reasonably, since folding it in would have reset that PR's green CI. #1452 exists so the fourth pass reads it instead of re-deriving it; this PR is that fourth pass acting on it, now that #1439 has merged and _format_json exists on main.

---

Generated by Claude Code

[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:03pm

[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: ba895112-b4c0-42fd-9cdc-a10c7ee27eaf

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

[groupthinking]

@coderabbitai review

Auto-review skipped again — same unsatisfiable label gate root-caused on #1439 and tracked in #1425 (reviews.auto_review.labels is one folded YAML scalar containing the whole bracketed list, so the "Required labels (at least one) (1)" count can never match a real label). Not re-filing; requesting manually, which is the working path.

This is a robustness fix on the error path of a security-sensitive formatter, so the claims worth attacking are specific:

1. Does the fallback actually cover every way json.dumps can raise here? I claim two: a circular container (rejected structurally before default is consulted) and a value whose __str__ raises (propagating out of default). If there is a third — something in formatException, a __reduce__-style hook, an exotic float — the guarantee is still overstated and I have reproduced the same defect I am fixing.

2. Can the fallback json.dumps itself raise? I claim not, because every value it receives is filtered to str/int/float/bool/None. If a str subclass or a float edge case (nan, inf) can break that, the record is still lost and the fix is incomplete.

3. Does the fallback preserve the fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429 guarantees? It is a second serialization path, so it must independently hold both: one physical line, and no attacker-forged field. I test this, but a second path is exactly where a security property quietly stops applying.

4. except Exception rather than a narrow tuple. Deliberate — (TypeError, ValueError, RecursionError) reads as more correct and the exploding-__str__ case walks straight through it. Worth challenging if it can now mask a bug that should surface loudly.

The thing I'd rather you catch than take on trust: _describe_exception guards against the caught exception's own __str__ raising. That is a real hazard here (the exception can originate in a call site's __str__), but if the reasoning is wrong it is dead code dressed as a safety property — which is the same "comment claims more than the code enforces" defect this PR exists to close.

Note for scope: .coderabbit.yaml path_filters contains !tests/**, so your review covers logging_config.py only. The 5 new tests are outside it, and CI's test job is the only third-party execution of them.

---

Generated by Claude Code

[groupthinking]

Three open PRs implement this same fix. Flagging once here rather than on each, since all three are drafts and only one can land.

PR	Title	Diff
#1471	keep the record when JSON serialization raises	+107 / −4
#1472	stop a bad enrichment value losing the whole JSON record	+133 / −4
#1477	keep the record when a JSON enrichment cannot serialize	+128 / −4

All three modify exactly src/youtube_extension/backend/config/logging_config.py and tests/unit/test_logging_config_crlf.py, and all three address the same residual risk #1439 named in its own Risk section — a non-serializable extra value raising inside json.dumps and losing the record. They appear to have been opened independently within minutes of #1439 merging (715cbf5).

MERGE_POLICY.md gate 6 applies: pick one implementation, close the other two with a pointer to the winner. Whichever lands first will conflict the other two on both files, so this is worth resolving before any of them is marked ready rather than after.

No opinion here on which is strongest — I have not reviewed the three approaches against each other, only established that they overlap.

---

Generated by Claude Code

[coderabbitai]

@groupthinking I will review the changes in logging_config.py, with focus on the fallback safety and the JSON security invariants.

---

✏️ Learnings added

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

Timestamp: 2026-08-07T20:56:30.460Z
Learning: In the EventRelay repository, automatic CodeRabbit review is currently blocked by `reviews.auto_review.labels`: the configured YAML value is one folded scalar containing the entire bracketed label list, so it cannot match an individual pull request label. Manual `coderabbitai review` requests are the working review path. The configuration defect is tracked in GitHub issue `#1425`.

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.

⚠️ 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]

Three open PRs implement #1452. Recommending this one as the winner, with #1471 and #1472 closed against it.

PR	Created	Approach
#1471	20:53:11	inline try/except, detail built inline
#1472	20:53:26	inline try/except, detail built inline, default=str on the fallback dump
#1477	20:55:44	extracts _describe_exception, unit-tested directly

MERGE_POLICY.md gate 6 breaks ties toward the fresher PR, which points here anyway. On the merits this is also the best-factored of the three: the "describing the exception must not itself raise" property is the subtle part, and it's the only version that names it, isolates it, and tests it in its own right (test_describe_exception_survives_an_exception_that_cannot_be_stringified) rather than only through the formatter.

The functional difference between the three is nil — #1471's fallback omits default=str and #1472's keeps it, but safe is filtered to JSON-native scalars first, so neither can reach it.

Independent verification

I reproduced the bug and the fix rather than taking the description on trust.

Against main (8c93de8), three records in, two out — the poisoned one vanishes with no error at the sink:

circular-container     emitted 2/3 records -> ['before', 'after']
exploding-__str__      emitted 2/3 records -> ['before', 'after']

Against this head:

circular-container     emitted 3/3 records -> ['before', 'poisoned', 'after']
exploding-__str__      emitted 3/3 records -> ['before', 'poisoned', 'after']

tests/unit/test_logging_config_crlf.py — 25 passed. ruff check — clean on both changed files.

On where this came from

The defect is mine. #1439 introduced default=str and its body asserted that it meant "a record is never lost to a serialization error." That was wrong in both directions this PR identifies: a circular container is rejected structurally before default is consulted, and a value whose __str__ raises propagates straight back out of it. The comment in the code said the same thing, so the claim was load-bearing for anyone reading it later. Correcting that framing — rather than just adding the try — is the part of this PR worth keeping.

Still a draft, so I'm not merging it; this is the reconciliation record, not an approval.

---

Generated by Claude Code

[groupthinking]

Red-team pass — one finding, fixed in 7af1ae5

Ran the runbook's step-5 adversarial pass over this diff with a real Python runtime, attacking the four claims above. Claim 1 was wrong, and in the same way this PR exists to correct: the comment asserted more than the code enforced.

Finding — a third input defeats default=str, and it does not raise

json.dumps renders a non-finite float as the JavaScript literals NaN / Infinity, which are not valid JSON. It does not raise, so the record is emitted and looks healthy — and then a strict downstream parser rejects it. That is the same loss the rest of this PR prevents, relocated to the consumer where it is much harder to see.

Reachable identically to the other two, via extra={"request_id": ...} → correlation_id. A duration-derived metric is a plausible source of inf.

json.loads accepts those literals by default, which is exactly why the suite could not catch it — the new tests assert against a strict parse (parse_constant= raising).

Fix: allow_nan=False on both dumps, turning it into a raise that routes to the fallback. _is_json_safe_scalar replaces the inline isinstance filter so the fallback drops non-finite floats too — otherwise the guard would just move the invalid literal one line down, which is what my first attempt did.

Also corrected: the scope of the guarantee

The comment said the fallback delivers "never lose a record". It does not, and I should not have written it that way. Building the payload can raise upstream of the try — record.getMessage() on mismatched %-args is the reachable case. It is out of scope because it fails the line-oriented path identically (super().format() calls getMessage() too), but the comment now says "serialization never loses one" rather than implying the broader property.

What held

10 probes, all one physical line of strictly-valid JSON with level authoritative:

Probe	Result
circular container · exploding __str__	record survives, enrichment dropped, cause reported
inf · -inf · nan	now strict-valid; previously emitted Infinity/NaN
20k-deep nesting (RecursionError)	caught by except Exception, record survives
exc_info whose __str__ raises	survives — formatException handles it upstream
lone surrogate \ud800	escaped, round-trips
#1429 forgery payload + poisoned enrichment	level stays INFO, no forged field — the fallback is a second serialization path and the security property holds on it too
benign scalar / finite float enrichment	normal path, no serialization_error
bad %-args	record lost — pre-existing, out of scope, now documented

Claims 2 and 4 held as stated: the fallback dump cannot raise (a str subclass with an exploding __str__ is still emitted directly by the encoder, never through default), and except Exception is load-bearing — the exploding-__str__ case raises RuntimeError and walks straight through (TypeError, ValueError, RecursionError).

Non-vacuity

Removing only allow_nan=False fails exactly the 3 non-finite tests (3 failed, 26 passed). The finite-float test keeps passing, so the guard is not simply rejecting all floats. Suite is 29 passed; ruff clean.

On the review

CodeRabbit accepted the request (1f2280d0) and then hit "Review limit reached — next review available in 53 minutes". Not re-triggering; the push above will re-arm it. Worth stating plainly that as of this comment no third party has reviewed this diff — and .coderabbit.yaml path_filters excludes tests/**, so when it does run, the 5 new tests stay out of scope and CI's test job remains their only third-party execution.

---

Generated by Claude Code

[groupthinking]

Superseded — #1452 landed as #1491 while this was open, so the base fix here is now on main.

Two findings in this PR are not on main and were the most valuable of the set:

• allow_nan=False — the merged code emits bare NaN/Infinity for a non-finite enrichment. Python's own json.loads accepts those, which is why existing tests missed it, but strict parsers reject the record. Confirmed against main.
• _describe_exception — the merged fallback builds serialization_error with f"{... }: {exc}", which can raise a second time out of the handler that was recovering from the first.

Both carried into #1497. Recommend closing this in favour of that one.

---

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

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