fix(logging): ship uvicorn filter instances only where dictConfig resolves them

`dictConfig` resolves each `filters` entry as an id into a top-level "filters"
section until Python 3.11 and raises ValueError on an instance, and uvicorn
applies this config from `Config.__init__`. pyproject declares >=3.10, so on the
floor of that range the proxy would fail to start with JSON_LOGS set rather than
log unredacted. Below 3.11 the entry is now empty, which `common_logger_config`
skips outright because it only resolves `filters` when the value is truthy. Those
runtimes keep the redaction `_redact_third_party_loggers` puts on uvicorn.error,
which survives `dictConfig` by living on the logger instead of in the config

The gate is a keyword argument defaulting to the version check so both branches
are reachable from tests on any interpreter, rather than patching a module global

Coverage for the gate itself is derived from what the running interpreter's
`dictConfig` actually does, not from restating the version literal, so a gate
that drifts from the runtime fails. A boundary wrong only on a version CI does
not run cannot be caught without that interpreter; the explicit-flag tests stand
in for it
This commit is contained in:
Alexander Azarov 2026-08-17 08:55:18 +01:00
parent f485ea4e73
commit 377ecd94db
2 changed files with 94 additions and 7 deletions

View file

@ -453,18 +453,35 @@ def _initialize_loggers_with_handler(handler: logging.Handler):
lg.propagate = False # prevent bubbling to parent/root
def _get_uvicorn_json_log_config():
_DICTCONFIG_TAKES_FILTER_INSTANCES: Final = sys.version_info >= (3, 11)
def _get_uvicorn_json_log_config(*, dictconfig_accepts_filter_instances: bool = _DICTCONFIG_TAKES_FILTER_INSTANCES):
"""
Generate a uvicorn log_config dictionary that applies JSON formatting to all loggers.
This ensures that uvicorn's access logs, error logs, and all application logs
are formatted as JSON when json_logs is enabled.
Redaction is attached here because uvicorn.access is the only logger that records the
request line, query string included, and routes such as /key/info take a credential as a
query parameter. Below Python 3.11 the filters are omitted rather than shipped: `dictConfig`
resolves every `filters` entry as an id into a top-level "filters" section until then and
raises on an instance, and uvicorn applies this config from `Config.__init__`, so shipping
instances would stop the proxy from starting. An empty entry is skipped outright by
`common_logger_config`, which only resolves `filters` when it is truthy. Those runtimes keep
the redaction `_redact_third_party_loggers` attaches to uvicorn.error, which survives
`dictConfig` because it is registered on the logger rather than in the config.
The flag is a parameter so both branches are reachable from tests on any interpreter.
"""
json_formatter_class: Final = "litellm._logging.JsonFormatter"
# Use the module-level log_level variable for consistency
uvicorn_log_level: Final = log_level.upper()
uvicorn_filters: Final = (_secret_filter,) if dictconfig_accepts_filter_instances else ()
log_config: Final = {
"version": 1,
"disable_existing_loggers": False,
@ -494,19 +511,19 @@ def _get_uvicorn_json_log_config():
"loggers": {
"uvicorn": {
"handlers": ["default"],
"filters": [_secret_filter],
"filters": uvicorn_filters,
"level": uvicorn_log_level,
"propagate": False,
},
"uvicorn.error": {
"handlers": ["default"],
"filters": [_secret_filter],
"filters": uvicorn_filters,
"level": uvicorn_log_level,
"propagate": False,
},
"uvicorn.access": {
"handlers": ["access"],
"filters": [_secret_filter],
"filters": uvicorn_filters,
"level": uvicorn_log_level,
"propagate": False,
},

View file

@ -489,7 +489,7 @@ def bare_uvicorn_loggers(uvicorn_logger_state):
yield
def _apply_uvicorn_json_log_config() -> None:
def _apply_uvicorn_json_log_config(*, dictconfig_accepts_filter_instances: bool = True) -> None:
"""Configure logging exactly as the proxy does when it starts uvicorn with JSON logs.
Call this from the test body, never from a fixture. The config's handlers write to
@ -497,8 +497,13 @@ def _apply_uvicorn_json_log_config() -> None:
that instant, and pytest swaps that object between the setup and call phases: resolving
it during setup captures the stream `capsys` is about to replace, and every assertion
then reads an empty buffer.
The flag is passed explicitly rather than left to the production default so these tests
describe one runtime's behavior instead of the interpreter that happens to run them.
"""
logging.config.dictConfig(_get_uvicorn_json_log_config())
logging.config.dictConfig(
_get_uvicorn_json_log_config(dictconfig_accepts_filter_instances=dictconfig_accepts_filter_instances)
)
def _emit_uvicorn_access_line(path: str, status: int = 200) -> None:
@ -615,7 +620,72 @@ def test_uvicorn_log_config_declares_secret_filter_on_every_logger():
The behavioral tests above only cover the loggers that exist today; this one fails when a
fourth is added unfiltered.
"""
loggers = _get_uvicorn_json_log_config()["loggers"]
loggers = _get_uvicorn_json_log_config(dictconfig_accepts_filter_instances=True)["loggers"]
unfiltered = tuple(name for name, cfg in loggers.items() if _secret_filter not in cfg.get("filters", ()))
assert unfiltered == (), f"uvicorn log config leaves these loggers unredacted: {unfiltered}"
def test_uvicorn_log_config_omits_filter_instances_below_python_311():
"""`dictConfig` resolves each `filters` entry as an id into a top-level "filters" section
until Python 3.11, and raises `ValueError` on an instance. uvicorn applies this config from
`Config.__init__`, so shipping instances at the floor of the supported range would stop the
proxy from starting rather than leave it logging unredacted. Empty is what makes that safe:
`common_logger_config` only resolves `filters` when the value is truthy.
"""
loggers = _get_uvicorn_json_log_config(dictconfig_accepts_filter_instances=False)["loggers"]
populated = tuple(name for name, cfg in loggers.items() if cfg["filters"])
assert populated == (), f"these loggers ship a filter dictConfig cannot resolve below 3.11: {populated}"
def _dictconfig_resolves_filter_instances() -> bool:
"""Whether this interpreter's `dictConfig` accepts a filter instance in a `filters` list.
Answered by trying it rather than by restating the version literal the gate uses, so a gate
that drifts from what the runtime actually supports fails the test below instead of agreeing
with itself.
"""
probe = logging.getLogger("test.dictconfig_filter_instance_probe")
config = {
"version": 1,
"disable_existing_loggers": False,
"loggers": {probe.name: {"filters": [_secret_filter]}},
}
try:
logging.config.dictConfig(config)
except ValueError:
return False
finally:
probe.filters.clear()
return True
def test_uvicorn_log_config_ships_filters_exactly_when_dictconfig_resolves_them():
"""The version gate itself, which every other test here bypasses by passing the flag.
The assertion is against what this interpreter's `dictConfig` actually does, so a gate that
disagrees with the runtime executing it fails here. A boundary that is wrong only on a
version this run is not using cannot be caught without that interpreter, which is what the
`dictconfig_accepts_filter_instances=False` tests stand in for.
"""
expected = (_secret_filter,) if _dictconfig_resolves_filter_instances() else ()
loggers = _get_uvicorn_json_log_config()["loggers"]
mismatched = tuple(name for name, cfg in loggers.items() if cfg["filters"] != expected)
assert mismatched == (), f"version gate disagrees with this interpreter's dictConfig for: {mismatched}"
def test_uvicorn_log_config_without_filter_instances_still_logs(bare_uvicorn_loggers, capsys):
"""Dropping the filters must cost redaction and nothing else.
The sub-3.11 config still has to be one uvicorn can apply, with the same handlers and the
same JSON formatter, so a request line comes out whole on those runtimes too.
"""
_apply_uvicorn_json_log_config(dictconfig_accepts_filter_instances=False)
logging.getLogger("uvicorn.access").setLevel(logging.INFO)
_emit_uvicorn_access_line("/health/liveliness")
message = json.loads(capsys.readouterr().out.strip())["message"]
assert message == '127.0.0.1:52814 - "GET /health/liveliness HTTP/1.1" 200'