From eefbe2eb18003cc843b83cefcf19cabb97b16e1c Mon Sep 17 00:00:00 2001 From: Yassin Kortam Date: Wed, 12 Aug 2026 12:37:15 -0700 Subject: [PATCH] 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. --- litellm/proxy/auth/user_api_key_auth.py | 30 +++++ .../proxy/auth/test_user_api_key_auth.py | 125 ++++++++++++++++++ 2 files changed, 155 insertions(+) diff --git a/litellm/proxy/auth/user_api_key_auth.py b/litellm/proxy/auth/user_api_key_auth.py index 4baa7b99a4f..f7a04ba79e7 100644 --- a/litellm/proxy/auth/user_api_key_auth.py +++ b/litellm/proxy/auth/user_api_key_auth.py @@ -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 diff --git a/tests/test_litellm/proxy/auth/test_user_api_key_auth.py b/tests/test_litellm/proxy/auth/test_user_api_key_auth.py index 60d9689dc0b..129813d806c 100644 --- a/tests/test_litellm/proxy/auth/test_user_api_key_auth.py +++ b/tests/test_litellm/proxy/auth/test_user_api_key_auth.py @@ -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."""