Skip to content

_format_json on main still drops records in two cases after #1491 (follow-up to #1452) #1499

Description

@groupthinking

Summary

#1491 merged as 8517bf8fb and closed #1452. It fixes the two headline cases, but the fallback it added still loses the record in two other cases, and emits invalid JSON in two more.

Reported because #1452's whole point was that the comment claimed more than the code enforced. The comment on main today says the fallback means "a bad enrichment costs its own value rather than the whole record". Measured against main, that is still not true.

Not a vulnerability, and not reachable from request content — an attacker-supplied header is a string, and strings serialize correctly. Same reachability as #1452: extra={"request_id": ...}correlation_id.

Reproduction

Against main @ 8517bf8fb. Three logger.info calls through a real StreamHandler, the middle one poisoned:

Input Result on main
circular container 3 of 3 — fixed by #1491
value whose __str__ raises 3 of 3 — fixed by #1491
value with a forged __class__ 2 of 3 — record lost
value whose __str__ raises an exception that itself raises 2 of 3 — record lost
inf 3 of 3, but not valid JSON (Infinity)
nan 3 of 3, but not valid JSON (NaN)

1. Forged __class__ — the filter disagrees with the encoder

class ForgedClassStr:
    @property
    def __class__(self): return str
    def __str__(self): raise RuntimeError("boom")

isinstance consults value.__class__, which this forges; json dispatches on the real runtime type. So the value passes the isinstance filter, reaches the fallback's own json.dumps — which on main carries default=str, so str() is called and raises — and the record is gone.

Two independent problems in one line: the filter is forgeable, and the fallback dump has default=str. Either alone would be enough. main:

safe = {k: v for k, v in payload.items()
        if isinstance(v, (str, int, float, bool, type(None)))}
safe["serialization_error"] = f"{type(exc).__name__}: {exc}"
return json.dumps(safe, ensure_ascii=True, default=str)

Fix: type(value) in {str, int, float, bool, type(None)}, and drop default= from the fallback dump — nothing may reach default on that path, because reaching it is what reinstates the raising-__str__ hole.

2. The error reporter is unguarded

safe["serialization_error"] = f"{type(exc).__name__}: {exc}"

{exc} calls the caught exception's own __str__. That exception can originate in a call site's __str__, so it can be an instance of a class whose __str__ also raises — and this raise happens inside the except block, where nothing catches it. The record is lost, by the code added to save it.

class ExplodingError(Exception):
    def __str__(self): raise RuntimeError("the error's own __str__ exploded")
class NestedExplodingStr:
    def __str__(self): raise ExplodingError()

Fix:

try:
    detail = f"{type(exc).__name__}: {exc}"
except Exception:  # noqa: BLE001 - the type name alone still identifies it
    detail = type(exc).__name__

Worth noting: all four of the other implementations of #1452 (#1471, #1472, #1477, #1488) had this guard. #1491 is the only one without it, and #1472 shipped a test (test_exception_whose_str_also_raises_does_not_lose_the_record) that fails on main today.

3. Non-finite floats produce invalid JSON

json.dumps renders inf/nan as the JavaScript literals Infinity/NaN, which are not valid JSON. It does not raise, so the record is emitted looking healthy and a strict downstream parser rejects it — the same loss as dropping it, moved to the consumer where it is harder to see. json.loads accepts those literals by default, which is why no test here catches it; asserting this needs parse_constant= raising.

Fix: allow_nan=False on both dumps, plus a math.isfinite check in the scalar filter so the fallback does not re-emit them.

Acceptance criteria

  1. A forged-__class__ value is emitted, not dropped, with level authoritative.
  2. An exception whose own __str__ raises is emitted, not dropped.
  3. inf / -inf / nan in an enrichment produce a record that parses under a strict JSON parser.
  4. Regression tests for all three, each failing on 8517bf8fb.
  5. The _format_json comment states the guarantee the code actually provides — and scopes it to serialization, since record.getMessage() on mismatched %-args still loses the record upstream of the guard (pre-existing, shared with the line-oriented path, out of scope).

Provenance

Findings 1 and 2 are #1471's and #1472's, from the four-way collision on #1452 — four sessions implemented that issue inside six minutes with no visibility of each other (comparison). Finding 3 is from a red-team pass on #1477.

#1491 was a fifth implementation and merged; the triage that selected it could not see the cross-PR analysis, which was posted minutes earlier on the other four. The mechanical result is that the merged version is the only one lacking the reporter guard. Filing rather than re-opening anything: #1477 was closed as superseded and stays closed, and no competing PR should be opened against #1452, which is correctly closed. This is a follow-up against what is on main now.

I have deliberately not opened a PR for this — the last round produced five for one issue, and a sixth without triage input would repeat exactly that. Happy to implement it on request; the patch is small and the three fixes are independent.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions