fix(proxy): log requests rejected for an unparsable body in spend logs (#36673)

A request whose body never parses is rejected in auth, before the endpoint
runs, so nothing downstream fires the failure hook that writes the spend log
row Request Logs reads. The caller sees a 400 that leaves no trace.

Auth now records that rejection through the same post_call_failure_hook the
endpoints use, keyed to the caller it already authenticated. Logging is
best-effort: a logging failure is swallowed so the 400 the caller sees is
unchanged. The path where the key is also rejected is left alone, since the
auth failure handler already logs that request.
This commit is contained in:
Yassin Kortam 2026-08-12 12:37:15 -07:00 committed by GitHub
parent a01b421ce9
commit eefbe2eb18
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
2 changed files with 155 additions and 0 deletions

View file

@ -1060,6 +1060,31 @@ async def _read_request_body_deferring_parse_failure(
return populate_request_with_path_params(request_data=parsed_body, request=request), None
async def _record_unparsable_body_failure(
user_api_key_dict: UserAPIKeyAuth,
body_parse_exception: ProxyException,
route: str,
) -> None:
"""Record the 400 an unparsable body earns as a failed request log.
The endpoint never runs for these, so no downstream failure hook writes the
spend log row the Admin UI reads. Logging must not change what the caller
sees, so a failure here is swallowed and the 400 is raised either way.
"""
from litellm.proxy.proxy_server import proxy_logging_obj
try:
await proxy_logging_obj.post_call_failure_hook( # pyright: ignore[reportUnknownMemberType] # bare dict in sig
request_data={}, # mutable-ok: the failure hook seeds the call id and metadata onto this dict
original_exception=body_parse_exception,
user_api_key_dict=user_api_key_dict,
error_type=ProxyErrorTypes.bad_request_error,
route=route,
)
except Exception as e: # noqa: BLE001 # any logging failure must leave the caller's 400 untouched
verbose_proxy_logger.exception("Failed to log the request rejected for an unparsable body: %s", e)
async def _user_api_key_auth_builder(
request: Request,
api_key: str,
@ -2673,6 +2698,11 @@ async def user_api_key_auth(
user_api_key_auth_obj.request_route = normalize_request_route(route)
if body_parse_exception is not None:
await _record_unparsable_body_failure(
user_api_key_dict=user_api_key_auth_obj,
body_parse_exception=body_parse_exception,
route=route,
)
raise body_parse_exception
# Resolve caller identity once, here at the seam, into a single per-request

View file

@ -4847,6 +4847,79 @@ async def test_user_api_key_auth_authenticates_before_raising_malformed_body_err
setattr(_proxy_server_mod, k, v)
async def _run_auth_with_malformed_body(post_call_failure_hook):
"""Drive ``user_api_key_auth`` for an authenticated caller whose body never parses,
with ``proxy_logging_obj.post_call_failure_hook`` swapped for the passed double.
Returns the raised ProxyException."""
from fastapi import Request
from starlette.datastructures import URL
import litellm.proxy.proxy_server as _proxy_server_mod
builder_token = UserAPIKeyAuth(api_key="sk-test", user_id="u1", team_id="team-1")
request = Request(
scope={
"type": "http",
"headers": [(b"content-type", b"application/json")],
"method": "POST",
}
)
request._url = URL(url="/chat/completions")
request._body = b'{}{"model": "gpt-4o"}'
attrs = _proxy_attrs_for_centralized_checks(user_custom_auth=None)
attrs["proxy_logging_obj"].post_call_failure_hook = post_call_failure_hook
originals = {a: getattr(_proxy_server_mod, a, None) for a in attrs}
try:
for k, v in attrs.items():
setattr(_proxy_server_mod, k, v)
with (
patch(
"litellm.proxy.auth.user_api_key_auth._user_api_key_auth_builder",
new_callable=AsyncMock,
return_value=builder_token,
),
patch(
"litellm.proxy.auth.user_api_key_auth.RouteChecks.should_call_route",
),
):
with pytest.raises(ProxyException) as exc_info:
await user_api_key_auth(request=request, api_key="Bearer sk-test")
return exc_info.value
finally:
for k, v in originals.items():
setattr(_proxy_server_mod, k, v)
@pytest.mark.asyncio
async def test_user_api_key_auth_logs_the_failure_for_a_body_that_never_parses():
"""The endpoint never runs for an unparsable body, so the 400 the caller sees only
reaches Request Logs if auth runs the failure hook that writes the spend log row."""
hook = AsyncMock(return_value=None)
raised = await _run_auth_with_malformed_body(hook)
assert "Invalid JSON payload" in str(raised.message)
assert raised.code == str(status.HTTP_400_BAD_REQUEST)
hook.assert_awaited_once()
hook_kwargs = hook.await_args.kwargs
assert hook_kwargs["original_exception"] is raised
assert hook_kwargs["error_type"] == ProxyErrorTypes.bad_request_error
assert hook_kwargs["route"] == "/chat/completions"
assert hook_kwargs["user_api_key_dict"].user_id == "u1"
assert hook_kwargs["user_api_key_dict"].team_id == "team-1"
@pytest.mark.asyncio
async def test_user_api_key_auth_returns_the_parse_error_even_if_logging_it_fails():
"""Logging the rejected request must never change what the caller sees."""
raised = await _run_auth_with_malformed_body(AsyncMock(side_effect=Exception("logging is down")))
assert "Invalid JSON payload" in str(raised.message)
assert raised.code == str(status.HTTP_400_BAD_REQUEST)
@pytest.mark.asyncio
async def test_user_api_key_auth_malformed_body_with_rejected_key_still_returns_the_parse_error():
"""The body is read before the key is authenticated, so a caller who sends both a
@ -4897,6 +4970,58 @@ async def test_user_api_key_auth_malformed_body_with_rejected_key_still_returns_
setattr(_proxy_server_mod, k, v)
@pytest.mark.asyncio
async def test_user_api_key_auth_does_not_double_log_a_malformed_body_from_a_rejected_key():
"""The auth failure this caller also earns is already logged by the handler that
rejected the key, so the unparsable-body hook must stay out of that path and leave
Request Logs with one row instead of two."""
from fastapi import Request
from starlette.datastructures import URL
import litellm.proxy.proxy_server as _proxy_server_mod
request = Request(
scope={
"type": "http",
"headers": [(b"content-type", b"application/json")],
"method": "POST",
}
)
request._url = URL(url="/chat/completions")
request._body = b'{}{"model": "gpt-4o"}'
hook = AsyncMock(return_value=None)
attrs = _proxy_attrs_for_centralized_checks(user_custom_auth=None)
attrs["proxy_logging_obj"].post_call_failure_hook = hook
originals = {a: getattr(_proxy_server_mod, a, None) for a in attrs}
try:
for k, v in attrs.items():
setattr(_proxy_server_mod, k, v)
with (
patch(
"litellm.proxy.auth.user_api_key_auth._user_api_key_auth_builder",
new_callable=AsyncMock,
side_effect=ProxyException(
message="Authentication Error, invalid key",
type="auth_error",
param="None",
code=status.HTTP_401_UNAUTHORIZED,
),
),
patch(
"litellm.proxy.auth.user_api_key_auth.RouteChecks.should_call_route",
),
):
with pytest.raises(ProxyException):
await user_api_key_auth(request=request, api_key="Bearer sk-bad")
await asyncio.sleep(0.05)
hook.assert_not_awaited()
finally:
for k, v in originals.items():
setattr(_proxy_server_mod, k, v)
def _proxy_attrs_for_db_lookup():
"""Minimal proxy_server attributes for driving the real
``_user_api_key_auth_builder`` down to the DB key lookup."""