Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 23 additions & 1 deletion src/youtube_extension/backend/config/logging_config.py
Original file line number Diff line number Diff line change
Expand Up @@ -76,6 +76,25 @@ def sanitize_log_record(rendered: str) -> str:
return rendered.translate(_UNSAFE_LOG_CHARS)


def _describe_exception(exc: BaseException) -> str:
"""Name an exception without trusting its ``__str__``.

Used only by ``StructuredFormatter._format_json``'s serialization
fallback. That fallback exists because a value whose ``__str__`` raises
costs the record — but the exception it catches is then *whatever that*
``__str__`` *raised*, which is arbitrary and may itself raise on
``str()``. Interpolating it directly would fail inside the handler for
the failure, losing the record for the same reason one level down.

The class name is the guaranteed-safe floor: an attribute lookup that
runs no user code.
"""
try:
return f"{type(exc).__name__}: {exc}"
except Exception: # noqa: BLE001 - the fallback must not need a fallback
return type(exc).__name__


class StructuredFormatter(logging.Formatter):
"""
Custom formatter for structured logging with enhanced metadata.
Expand Down Expand Up @@ -172,7 +191,10 @@ def _format_json(self, record: logging.LogRecord) -> str:
for key, value in payload.items()
if isinstance(value, (str, int, float, bool, type(None)))
}
safe["serialization_error"] = f"{type(exc).__name__}: {exc}"
# Described via `_describe_exception`, not interpolated directly:
# `exc` is whatever the offending `__str__` raised, so `str(exc)`
# can raise in turn and cost the record here instead.
safe["serialization_error"] = _describe_exception(exc)
return json.dumps(safe, ensure_ascii=True, default=str)

def formatException(self, ei) -> str:
Expand Down
49 changes: 49 additions & 0 deletions tests/unit/test_logging_config_crlf.py
Original file line number Diff line number Diff line change
Expand Up @@ -369,6 +369,55 @@ def test_exploding_str_correlation_id_does_not_cost_the_record():
assert poisoned["serialization_error"] == "RuntimeError: str() exploded"


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


def test_fallback_survives_an_exception_whose_own_str_raises():
"""The fallback must not need a fallback.

`exc` here is not `json`'s own error — it is whatever the offending
`__str__` raised, so it is arbitrary caller code. If that exception also
raises on `str()`, interpolating it into `serialization_error` fails
*inside the handler for the failure*, and the record is lost for exactly
the reason the fallback exists to prevent. Measured at 2 of 3 records
reaching the sink before `_describe_exception`.
"""

class _NastyError(Exception):
def __str__(self) -> str:
raise RuntimeError("even the error explodes")

class _RaisesNasty:
def __str__(self) -> str:
raise _NastyError()

records = _emit_three("json-nested-explosion", _RaisesNasty())

assert len(records) == 3
poisoned = records[1]
assert poisoned["message"] == "poisoned"
assert poisoned["level"] == "INFO"
assert "correlation_id" not in poisoned
# Degraded to the class name alone rather than lost entirely.
assert poisoned["serialization_error"] == "_NastyError"


def test_serialization_fallback_still_escapes_attacker_content():
# The fallback must not become a hole in the #1429 fix: a forgery payload
# in `message` has to stay escaped on the degraded path too.
Expand Down
Loading