fix(logging): close the three holes the #1452 fallback shipped with by groupthinking · Pull Request #1504 · groupthinking/EventRelay

groupthinking · 2026-08-07T21:11:35Z

Canonical issue

Reopening the scope of #1452 rather than filing a new issue: its acceptance criterion was "a record is never lost to a serialization error." #1491 landed the fallback that makes that mostly true. This PR is what makes it true without a qualifier — the same overclaim #1452 was filed about, one level down.

Outcome

_format_json's serialization fallback can no longer fail the way the serialization it guards failed.

#1491 landed the #1452 fallback: when json.dumps raises, re-serialize from the scalar fields so a bad enrichment costs its own value rather than the whole record. The retry itself contains three steps that can raise — inside the handler that exists because raising is the failure mode.

Measured against 8517bf8 (the merged #1491) with the same healthy → poisoned → healthy probe the existing tests use:

Hole	Mechanism	Measured on `8517bf8`
Forged `__class__`	`isinstance(value, str)` consults `value.__class__`, which a property can forge. The value passes the filter, reaches a `json.dumps` that still carried `default=str`, and its raising `__str__` kills the record.	2 of 3 records reach the sink
Unrenderable exception	`f"{type(exc).__name__}: {exc}"` renders the caught exception unguarded. An exception whose own `__str__` raises kills the record.	2 of 3 records reach the sink
Non-finite float	Serializes to the bare literal `NaN`, which is not valid JSON. The record reaches the sink and is then rejected by any strict parser.	3 of 3 at the sink, 0 usable downstream

The third is the one worth being precise about: the record is not lost at the sink, it is lost after it, where nothing can degrade it into something parseable. Routing it through the fallback trades an unparseable record for a degraded one.

How each is closed

_is_json_safe_scalar matches the exact runtime type, never isinstance. json itself dispatches on the real runtime type, which cannot be forged, so matching on it makes the filter agree with the encoder rather than merely resemble it. It also excludes non-finite floats.
_describe_exception names an exception without trusting its __str__, degrading to the bare class name — an attribute, so naming it cannot itself raise.
The retry drops default= entirely. Anything reaching default there would reinstate the raising-__str__ hole; the filter has already excluded everything that would, so default is not just unnecessary but actively wrong.
allow_nan=False on the primary dump is what routes a non-finite enrichment to the fallback instead of emitting an unparseable record.
A module-level constant is the floor, so emitting the last-resort record cannot itself fail.

Scope

Included:
- logging_config.py — _describe_exception, _is_json_safe_scalar, _JSON_UNSERIALIZABLE_RECORD, and the reworked retry.
- tests/unit/test_logging_config_crlf.py — +6 tests in the existing CWE-117 file, in its established idiom.
Explicitly excluded:
- Detection and escaping logic. The fix(security): CWE-117 JSON field forgery via unescaped " survives the #1270 log sanitizer #1429/fix(security): build JSON log records with json.dumps (CWE-117 field forgery) #1439 CWE-117 field-forgery guarantee is untouched and still pinned by its own 23 tests, including on the degraded path.
- The JSON_LOGGING default mismatch (production_config.py:72 says "true", logging_config.py says "false"). Scoped out of fix(security): build JSON log records with json.dumps (CWE-117 field forgery) #1439 and fix(logging): keep the record when JSON serialization fails (#1452) #1491 for the same reason: a behavioural config decision, not a serialization fix.
- record.getMessage(). A lazy %s argument whose __str__ raises fails while the payload is still being built, above the retry. It fails identically on the line-oriented path, so it is not specific to JSON and not this PR's to fix.

Note: this consolidates six competing pull requests

At the time of writing, six open PRs implement #1452 — #1471, #1472, #1477, #1488, #1493 and #1494 — all opened within eleven minutes of each other, after #1491 had already merged the base fix. Each caught a different subset of the residual holes; none caught all three. This PR is their union, verified rather than merged on trust:

fix(logging): keep the record when JSON serialization raises #1471 / fix(logging): keep the record when a JSON enrichment cannot serialize #1477 — the forged-__class__ hole and the type()-not-isinstance argument.
fix(logging): keep the record when a JSON enrichment cannot serialize #1477 — the non-finite float case.
fix(logging): keep the record when JSON serialization fails #1493 / fix(logging): stop the serialization fallback from needing a fallback #1494 — the unguarded exception rendering.
fix(logging): never lose a JSON log record to a serialization error #1488 — the constant last-resort record.
fix(logging): stop a bad enrichment value losing the whole JSON record #1472 — the precise scoping of what the guard does and does not cover, reflected in the exclusions above.

Under MERGE_POLICY.md gate 6, the six need a reconciliation decision, not six rebases. Recommendation is on the table in the PR thread; they are left open pending it rather than closed unilaterally.

Risk

Risk level: low
Failure mode: two of the three paths are reached only when the record is already being lost, so the worst case there is a degraded record where today there is none. The one genuine behaviour change is allow_nan=False on the primary dump: a record carrying a non-finite performance_ms now emits degraded-but-parseable instead of {"performance_ms": NaN}. That is a widening of what survives, and the previous output was not valid JSON, so no conforming consumer can regress. A consumer relying on Python's own json.loads (which accepts NaN) to read that field would see it drop to serialization_error — no such consumer exists in-tree.
Rollback: git revert. No migration, config, or schema change.

Verification

Head 7358509. Measured, not inferred.

Focused tests — tests/unit/test_logging_config_crlf.py: 29 passed. The 23 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 default=str in _format_json does not deliver its stated guarantee — a record can still be lost (follow-up to #1439) #1452 contract are intact.

Non-vacuous, and precisely scoped. Reverting only logging_config.py to origin/main and keeping the tests fails exactly the six new tests and nothing else:

FAILED test_forged_class_cannot_smuggle_a_raising_str_into_the_fallback
FAILED test_unrenderable_exception_does_not_cost_the_record
FAILED test_non_finite_enrichment_still_yields_strictly_valid_json[nan]
FAILED test_non_finite_enrichment_still_yields_strictly_valid_json[inf]
FAILED test_non_finite_enrichment_still_yields_strictly_valid_json[-inf]
FAILED test_fallback_of_last_resort_is_emitted_rather_than_nothing
6 failed, 23 passed

The non-finite test cannot pass against the bug. json.loads accepts NaN/Infinity by default, so asserting "it parses" would pass on unfixed code. The test passes a parse_constant that fires on exactly those literals — which is what a strict downstream parser rejects.
The degraded path is still 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 (pre-existing) drives the forgery payload through the fallback and still passes; the new tests additionally assert level stays authoritative on every degraded record.
except Exception is deliberate. A narrow (TypeError, ValueError, RecursionError) walks straight past the exploding-__str__ cases; the tests fail against the narrow version.
Blast radius checked, not assumed. tests/unit/test_logging_config_crlf.py is the only test file in the repo referencing logging_config.
Lint — ruff check clean on both changed files.
Required CI — pending first run on this head.
Review threads resolved — none open yet.

Stated honestly: the wider tests/unit/ suite could not be run in this sandbox — 61 collection errors, all ModuleNotFoundError for project dependencies (fastapi, pydantic, aiohttp, psutil, aiofiles) that are not installed here. logging_config imports none of them, and the file under test collects and runs cleanly. CI covers the rest.

Production evidence

Not applicable as a preview — 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 8517bf8 for both raising cases, 3 of 3 on this head, plus strict-parser rejection of the non-finite record before and acceptance after.

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 — six do (fix(logging): keep the record when JSON serialization raises #1471, fix(logging): stop a bad enrichment value losing the whole JSON record #1472, fix(logging): keep the record when a JSON enrichment cannot serialize #1477, fix(logging): never lose a JSON log record to a serialization error #1488, fix(logging): keep the record when JSON serialization fails #1493, fix(logging): stop the serialization fallback from needing a fallback #1494). This PR is their consolidation and is proposed as the one to land; the others need a reconciliation decision under gate 6. Flagged rather than checked, because checking it would be false.
Acceptance criteria are satisfied — default=str in _format_json does not deliver its stated guarantee — a record can still be lost (follow-up to #1439) #1452's fourth criterion ("the comment states the real guarantee") is what this PR is about: the comment fix(logging): keep the record when JSON serialization fails (#1452) #1491 shipped described a guarantee its code did not yet provide.
Required checks pass on the current head — first run pending
Human decision is requested only for: merge approval, and the gate-6 reconciliation of the six competing PRs

Generated by Claude Code

#1491 landed the #1452 fallback: when `json.dumps` raises, re-serialize from the scalar fields so a bad enrichment costs its own value rather than the whole record. The retry itself contains three steps that can raise -- inside the handler that exists because raising is the failure mode. Measured against 8517bf8 with a healthy -> poisoned -> healthy probe: 1. `isinstance(value, str)` consults `value.__class__`, which a property can forge. The value passes the filter, reaches a `json.dumps` that still carried `default=str`, and its raising `__str__` kills the record. 2 of 3 records reach the sink. 2. `f"{type(exc).__name__}: {exc}"` renders the caught exception unguarded. An exception whose own `__str__` raises kills the record. 2 of 3. 3. A non-finite float serializes to the bare literal `NaN`, which is not valid JSON. The record reaches the sink and is then rejected by any strict parser -- lost downstream, where nothing can degrade it, instead of at the sink, where the fallback can. `_is_json_safe_scalar` matches the exact runtime type, which cannot be forged and is what `json` itself dispatches on, and excludes non-finite floats. `_describe_exception` names an exception without trusting its `__str__`. The retry drops `default=` entirely, so nothing on that path can reach `str()`; the filter has already excluded everything that would. `allow_nan=False` on the primary dump is what routes a non-finite enrichment to the fallback rather than emitting an unparseable record. A module-level constant is the floor, so the guarantee holds without a qualifier. Consolidates the residual findings from six competing pull requests against #1452 (#1471, #1472, #1477, #1488, #1493, #1494), each of which caught a different subset. Credit to #1471/#1477 for the forged-`__class__` hole, #1477 for the non-finite case, #1493/#1494 for the exception rendering, and #1488 for the constant floor. Verification: 29 passed in tests/unit/test_logging_config_crlf.py. Reverting only logging_config.py fails exactly the 6 new tests and no others (6 failed, 23 passed), so they are non-vacuous and scoped. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01DDs1q8Pw4i5y3wbBSaUf8V

vercel · 2026-08-07T21:11:41Z

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:12pm

coderabbitai · 2026-08-07T21:11:44Z

Warning

Review limit reached

@groupthinking, you've reached your PR review limit, so we couldn't start this review.

Next review available in: 37 minutes

You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository.

How can I continue?

After more reviews become available, a review can be triggered using the @coderabbitai review command as a PR comment. Alternatively, push new commits to this PR.

To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based reviews.

How do review limits work?

CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan review availability.

For paid Pro and Pro+ PR reviews, CodeRabbit uses adaptive limits for sustained high-volume activity. When a developer's recent PR review activity reaches the 95th percentile or higher among CodeRabbit users, additional reviews become available more gradually as earlier reviews age out of the rolling window.

Please refer docs for additional details.

Review details

⚙️ Run configuration

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

Review profile: ASSERTIVE

Plan: Pro Plus

Run ID: 3e8cd06d-374d-46c2-830b-279274b9f1c9

📥 Commits

Reviewing files that changed from the base of the PR and between b7a2da3 and 7358509.

⛔ Files ignored due to path filters (1)

tests/unit/test_logging_config_crlf.py is excluded by !tests/**

📒 Files selected for processing (1)

src/youtube_extension/backend/config/logging_config.py

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

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

groupthinking · 2026-08-07T21:12:14Z

@coderabbitai full review

(Auto-review skipped for want of a qualifying label — the exact failure mode MERGE_POLICY.md v2 records under "Gates nobody could satisfy". The label job should attach python/tests on this head; triggering explicitly so the review does not wait on it.)

Generated by Claude Code

coderabbitai · 2026-08-07T21:12:24Z

@groupthinking I will run a full review of #1504.

⚠️ Action not completed

Review rate limited.

Your included review limit is currently reached under our Fair Usage Limits Policy. This review may still proceed through usage-based billing if eligible. Your next included review will be available in 37 minutes.

groupthinking · 2026-08-07T21:13:28Z

This supersedes #1494 — closing that one in favour of this. One salvageable test.

I opened #1494 from a scheduled remediation run at 21:04, about seven minutes before this PR, having independently found hole 2 (the unguarded f"...{exc}"). This PR is a strict superset: the _describe_exception implementation here is functionally identical to mine, and holes 1 and 3 — the forged __class__ and the non-finite float — I did not find. I have closed #1494 rather than leave three competing PRs on the same twenty lines.

Two notes worth carrying over.

One test #1494 has that this PR does not

The enrichment loop reads two attributes:

for attribute in ("performance_ms", "correlation_id"):

Every test here and in #1491 poisons correlation_id — via _emit_three, which hardcodes extra={"request_id": poison}. performance_ms has no coverage on any of the three PRs, and it reaches the payload by a different route: set from record.duration inside format(), or passed straight through extra=. The filter is per-value, so it should behave identically — which is exactly the kind of "should" that earns a cheap test:

def test_exploding_str_performance_ms_does_not_cost_the_record():
    # `correlation_id` is covered above, but the enrichment loop reads *two*
    # attributes and `performance_ms` is the other one. It arrives by a
    # different route — set from `record.duration` in `format()`, or straight
    # from `extra=` as here — so covering only `correlation_id` leaves half
    # the reachable surface untested.
    logger, buf = _make_json_logger("json-exploding-perf")
    logger.info("healthy one")
    logger.info("poisoned", extra={"performance_ms": _ExplodingStr()})
    logger.info("after poison")
    records = [json.loads(line) for line in buf.getvalue().splitlines() if line.strip()]

    assert len(records) == 3
    poisoned = records[1]
    assert poisoned["message"] == "poisoned"
    assert poisoned["level"] == "INFO"
    assert "performance_ms" not in poisoned

To be straight about what it is: this passes on 8517bf8, so it closes a coverage gap rather than pinning a fix. It does not belong in this PR's "every test below fails on 8517bf8" block — it would falsify that header. Worth adding just below it with its own note, or skipping deliberately.

One thing to double-check in `_ForgedClass`

The forged-__class__ probe is the sharpest finding of the three, and it rests on json's C encoder dispatching on the real runtime type while isinstance consults the forged __class__. That is right, and the fix (type(value) is) is the correct shape.

The bit worth confirming rather than assuming is that the test fails on 8517bf8 for the stated reason — the forged value passing the isinstance filter and then raising in the fallback's default=str — and not because @property __class__ upsets something earlier, in hasattr/getattr in the enrichment loop or in the primary dump. Both paths end in a dropped record and "2 of 3", so the measurement alone does not separate them. If the primary dump is where it dies, the value never reaches the filter and the test is passing for a reason other than the one the comment gives.

Cheap to settle: assert poisoned["serialization_error"] names the exception you expect from the fallback path specifically, rather than only asserting the key is present.

Terminal state for #1494: closed as superseded. No commits from it need porting beyond the test above; its _describe_exception and this PR's are the same code.

Generated by Claude Code

groupthinking · 2026-08-07T21:14:53Z

Duplicate cluster: #1494 ⊂ #1497 ⊂ #1504

Flagging from an unattended PR-remediation sweep. Three open PRs — #1494, #1497 and this one — change the same two files (src/youtube_extension/backend/config/logging_config.py, tests/unit/test_logging_config_crlf.py) and were opened within seven minutes of each other (21:04, 21:05, 21:11 UTC). They are not complementary; they are nested re-implementations of the same follow-up to #1452.

Compared by diff, not by description:

PR	`_describe_exception`	`_is_json_safe_scalar` (exact-type + `isfinite`)	`allow_nan=False`	last-resort constant
#1494	✅	—	—	—
#1497	✅	✅	✅	—
#1504	✅	✅	✅	✅

Each is a strict subset of the next. The test files overlap the same way — #1497 and #1504 both add a forged-__class__ value class, an exploding-__str__ exception class, and a non-finite-float parametrisation, differing only in naming (_ExplodingExc / _UnrenderableExc).

Consequence if left as-is: whichever lands first leaves the other two conflicted on the same hunks, and the two behind it will read as "already fixed" to a reviewer skimming titles. All three also each fire ~25 CI jobs per push into a queue currently 285 runs deep.

Suggested resolution: keep this PR as canonical, close #1494 and #1497 as superseded. No unique behaviour is lost — the table above is the complete delta. Flagging rather than closing them myself: which one is canonical is a maintainer call, and the diffs are not identical in comment wording or test naming even where they are identical in behaviour.

Not a review of this PR's substance — its own gates still apply.

Generated by Claude Code

groupthinking · 2026-08-07T21:16:15Z

Closing this as a duplicate of #1497, which is the same fix and opened six minutes earlier (21:05 vs 21:11).

I opened this PR after finding that #1491's fallback still dropped records, having scanned the six then-open #1452 PRs and confirmed none of them closed all three holes. What I did not check was whether a seventh had appeared while I was working. #1497 had, and it is the same consolidation: exact-type scalar filter, guarded exception naming, allow_nan=False, no default= on the retry. I verified it rather than taking its description on trust — it holds 3 of 3 records against my own adversarial battery (forged __class__, exploding __str__, NaN/±inf, RecursionError, 2000-deep nesting, bytes).

This is the same duplicate-PR failure this sweep was opened to reduce, and I reproduced it. Worth recording plainly rather than quietly closing:

The six competing default=str in _format_json does not deliver its stated guarantee — a record can still be lost (follow-up to #1439) #1452 PRs (fix(logging): keep the record when JSON serialization raises #1471, fix(logging): stop a bad enrichment value losing the whole JSON record #1472, fix(logging): keep the record when a JSON enrichment cannot serialize #1477, fix(logging): never lose a JSON log record to a serialization error #1488, fix(logging): keep the record when JSON serialization fails #1493, fix(logging): stop the serialization fallback from needing a fallback #1494) all opened after fix(logging): keep the record when JSON serialization fails (#1452) #1491 had already merged the base fix.
fix(logging): close three residual record-loss holes in the JSON fallback #1497 and this PR then both consolidated their residuals, independently, minutes apart.
Eight PRs for one issue. The scan that would have caught it — re-listing open PRs immediately before opening a new one — takes one API call, and neither of us made it.

The one thing this pass produced that #1497 does not already have is a finding, now handed over in #1497's thread: _describe_exception re-evaluates type(exc).__name__ unguarded in its own except branch, so an exception whose metaclass makes __name__ raise still costs the record — 2 of 3 on #1497's head, and 2 of 3 on this branch too. The gap survived both passes; it is not a reason to prefer this PR over that one.

Branch claude/clever-heisenberg-a0dh4r is left in place should the measurements or the tests be wanted; nothing here needs to merge.

Generated by Claude Code

github-actions · 2026-08-07T21:27:06Z

Dependency Review

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

Snapshot Warnings

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

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

groupthinking mentioned this pull request Aug 7, 2026

fix(logging): stop the serialization fallback from needing a fallback #1494

Closed

13 tasks

vercel Bot deployed to Preview August 7, 2026 21:12 View deployment

groupthinking mentioned this pull request Aug 7, 2026

fix(logging): close three residual record-loss holes in the JSON fallback #1497

Closed

10 tasks

groupthinking closed this Aug 7, 2026

This was referenced Aug 7, 2026

_format_json still loses records after #1491 — four holes, nine PRs, none merged #1505

Closed

fix(logging): close three ways the JSON fallback still lost the record #1515

Merged

groupthinking mentioned this pull request Aug 7, 2026

test(web): pin both edges of the SSRF guard's IPv6 bit-mask ranges #1512

Merged

13 tasks

github-actions Bot added the python label Aug 7, 2026

groupthinking mentioned this pull request Aug 7, 2026

fix(logging): stop a hostile metaclass costing the record #1516

Merged

11 tasks

Navigation Menu

fix(logging): close the three holes the #1452 fallback shipped with - #1504

fix(logging): close the three holes the #1452 fallback shipped with#1504
groupthinking wants to merge 1 commit into
mainfrom
claude/clever-heisenberg-a0dh4r

groupthinking commented Aug 7, 2026

Uh oh!

vercel Bot commented Aug 7, 2026 •

edited

Loading

Uh oh!

coderabbitai Bot commented Aug 7, 2026 •

edited

Loading

Review limit reached

Uh oh!

groupthinking commented Aug 7, 2026

Uh oh!

coderabbitai Bot commented Aug 7, 2026 •

edited

Loading

Uh oh!

groupthinking commented Aug 7, 2026

Uh oh!

groupthinking commented Aug 7, 2026

Uh oh!

groupthinking commented Aug 7, 2026

Uh oh!

github-actions Bot commented Aug 7, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Conversation

groupthinking commented Aug 7, 2026

Canonical issue

Outcome

How each is closed

Scope

Note: this consolidates six competing pull requests

Risk

Verification

Production evidence

Agent handoff

Uh oh!

vercel Bot commented Aug 7, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

coderabbitai Bot commented Aug 7, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Review limit reached

Uh oh!

groupthinking commented Aug 7, 2026

Uh oh!

coderabbitai Bot commented Aug 7, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

groupthinking commented Aug 7, 2026

This supersedes #1494 — closing that one in favour of this. One salvageable test.

One test #1494 has that this PR does not

One thing to double-check in _ForgedClass

Uh oh!

groupthinking commented Aug 7, 2026

Duplicate cluster: #1494 ⊂ #1497 ⊂ #1504

Uh oh!

groupthinking commented Aug 7, 2026

Uh oh!

github-actions Bot commented Aug 7, 2026

Dependency Review

Snapshot Warnings

Scanned Files

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

vercel Bot commented Aug 7, 2026 •

edited

Loading

coderabbitai Bot commented Aug 7, 2026 •

edited

Loading

coderabbitai Bot commented Aug 7, 2026 •

edited

Loading

One thing to double-check in `_ForgedClass`