From efeaf650aace39e708d35dbdfe161b6a3c610579 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Benedikt=20=C3=93skarsson?= Date: Thu, 26 Feb 2026 08:08:35 +0000 Subject: [PATCH] fix(proxy): improve auth exception logging levels and add structured context (#22099) * fix(proxy): improve auth exception logging levels and add structured context Downgrade expected auth failures (ProxyException, HTTPException < 500, BudgetExceededError) from ERROR to WARNING log level to reduce noise from routine rejected requests (e.g. missing/invalid API keys on polled endpoints like /schedule/model_cost_map_reload/status). Unexpected exceptions and HTTPException with status >= 500 still log at ERROR with full traceback. Enrich log messages with structured context: route, HTTP method, masked API key (using existing abbreviate_api_key), error type, and error code. All fields also passed via log extra dict for log aggregation tools. Fixes #21293 * Update tests/test_litellm/proxy/auth/test_auth_exception_handler.py Co-authored-by: greptile-apps[bot] <165735046+greptile-apps[bot]@users.noreply.github.com> --------- Co-authored-by: greptile-apps[bot] <165735046+greptile-apps[bot]@users.noreply.github.com> --- litellm/proxy/auth/auth_exception_handler.py | 70 ++++++- .../proxy/auth/test_auth_exception_handler.py | 196 ++++++++++++++++++ 2 files changed, 259 insertions(+), 7 deletions(-) diff --git a/litellm/proxy/auth/auth_exception_handler.py b/litellm/proxy/auth/auth_exception_handler.py index 9c306acd2c..4e35abf696 100644 --- a/litellm/proxy/auth/auth_exception_handler.py +++ b/litellm/proxy/auth/auth_exception_handler.py @@ -9,7 +9,7 @@ from fastapi import HTTPException, Request, status import litellm from litellm._logging import verbose_proxy_logger from litellm.proxy._types import ProxyErrorTypes, ProxyException, UserAPIKeyAuth -from litellm.proxy.auth.auth_utils import _get_request_ip_address +from litellm.proxy.auth.auth_utils import _get_request_ip_address, abbreviate_api_key from litellm.proxy.db.exception_handler import PrismaDBExceptionHandler from litellm.types.services import ServiceTypes @@ -75,13 +75,69 @@ class UserAPIKeyAuthExceptionHandler: request=request, use_x_forwarded_for=general_settings.get("use_x_forwarded_for", False), ) - verbose_proxy_logger.exception( - "litellm.proxy.proxy_server.user_api_key_auth(): Exception occured - {}\nRequester IP Address:{}".format( - str(e), - requester_ip, - ), - extra={"requester_ip": requester_ip}, + + # Build structured context for the log message + masked_key = abbreviate_api_key(api_key=api_key) if api_key else "None" + http_method = getattr(request, "method", "UNKNOWN") + + # Extract error category and status code from typed exceptions + if isinstance(e, ProxyException): + error_type = e.type + error_code = e.code + elif isinstance(e, HTTPException): + error_type = "http_exception" + error_code = str(getattr(e, "status_code", "unknown")) + elif isinstance(e, litellm.BudgetExceededError): + error_type = "budget_exceeded" + error_code = "400" + else: + error_type = type(e).__name__ + error_code = "401" + + log_extra = { + "requester_ip": requester_ip, + "route": route, + "api_key": masked_key, + "error_type": error_type, + "error_code": error_code, + "http_method": http_method, + } + + # Use warning level for expected auth failures to avoid noisy ERROR logs + # and full tracebacks for routine rejected requests (e.g. missing/invalid key). + # Reserve ERROR + traceback for truly unexpected exceptions and server errors. + _is_expected_auth_error = isinstance( + e, (ProxyException, litellm.BudgetExceededError) + ) or ( + isinstance(e, HTTPException) + and getattr(e, "status_code", 500) < 500 ) + if _is_expected_auth_error: + verbose_proxy_logger.warning( + "Auth failed: error_type={}, error_code={}, route={} {}, api_key={}, ip={} - {}".format( + error_type, + error_code, + http_method, + route, + masked_key, + requester_ip, + str(e), + ), + extra=log_extra, + ) + else: + verbose_proxy_logger.exception( + "Auth exception: error_type={}, error_code={}, route={} {}, api_key={}, ip={} - {}".format( + error_type, + error_code, + http_method, + route, + masked_key, + requester_ip, + str(e), + ), + extra=log_extra, + ) # Log this exception to OTEL, Datadog etc user_api_key_dict = UserAPIKeyAuth( diff --git a/tests/test_litellm/proxy/auth/test_auth_exception_handler.py b/tests/test_litellm/proxy/auth/test_auth_exception_handler.py index 3e780c6ee9..8952e67d6d 100644 --- a/tests/test_litellm/proxy/auth/test_auth_exception_handler.py +++ b/tests/test_litellm/proxy/auth/test_auth_exception_handler.py @@ -152,3 +152,199 @@ async def test_route_passed_to_post_call_failure_hook(): mock_post_call_failure_hook.assert_called_once() call_args = mock_post_call_failure_hook.call_args[1] assert call_args["user_api_key_dict"].request_route == test_route + + +@pytest.mark.asyncio +async def test_expected_auth_errors_log_at_warning_level(): + """ + Expected auth failures (ProxyException, HTTPException < 500, BudgetExceededError) + should log at WARNING level, not ERROR, to reduce log noise. + """ + handler = UserAPIKeyAuthExceptionHandler() + + mock_request = MagicMock() + mock_request.method = "GET" + mock_request_data = {} + mock_route = "/schedule/model_cost_map_reload/status" + mock_span = None + mock_api_key = "sk-test1234" + + expected_auth_errors = [ + ProxyException( + message="Token not found", + type=ProxyErrorTypes.token_not_found_in_db, + param="key", + code=401, + ), + HTTPException(status_code=401, detail="Invalid API key"), + HTTPException(status_code=403, detail="Forbidden"), + ] + + for error in expected_auth_errors: + with patch( + "litellm.proxy.proxy_server.general_settings", + {"allow_requests_on_db_unavailable": False}, + ), patch.object( + verbose_proxy_logger, "warning" + ) as mock_warning, patch.object( + verbose_proxy_logger, "exception" + ) as mock_exception: + try: + await handler._handle_authentication_error( + error, + mock_request, + mock_request_data, + mock_route, + mock_span, + mock_api_key, + ) + except Exception: + pass + + assert mock_warning.call_count == 1, ( + f"Expected warning log for {type(error).__name__}, got none" + ) + assert mock_exception.call_count == 0, ( + f"Did not expect exception log for {type(error).__name__}" + ) + + +@pytest.mark.asyncio +async def test_unexpected_errors_log_at_error_level(): + """ + Unexpected exceptions (bare Exception, HTTPException with 500) should + still log at ERROR level with full traceback. + """ + handler = UserAPIKeyAuthExceptionHandler() + + mock_request = MagicMock() + mock_request.method = "POST" + mock_request_data = {} + mock_route = "/chat/completions" + mock_span = None + mock_api_key = "sk-test1234" + + unexpected_errors = [ + Exception("Something unexpected broke"), + HTTPException(status_code=500, detail="Master key type error"), + ] + + for error in unexpected_errors: + with patch( + "litellm.proxy.proxy_server.general_settings", + {"allow_requests_on_db_unavailable": False}, + ), patch.object( + verbose_proxy_logger, "warning" + ) as mock_warning, patch.object( + verbose_proxy_logger, "exception" + ) as mock_exception: + try: + await handler._handle_authentication_error( + error, + mock_request, + mock_request_data, + mock_route, + mock_span, + mock_api_key, + ) + except Exception: + pass + + mock_exception.assert_called_once(), ( + f"Expected exception log for {type(error).__name__}, got none" + ) + mock_warning.assert_not_called(), ( + f"Did not expect warning log for {type(error).__name__}" + ) + + +@pytest.mark.asyncio +async def test_auth_error_log_contains_structured_context(): + """ + Log messages should include route, HTTP method, masked API key, error type, + and error code for easier debugging. + """ + handler = UserAPIKeyAuthExceptionHandler() + + mock_request = MagicMock() + mock_request.method = "GET" + mock_request_data = {} + mock_route = "/schedule/model_cost_map_reload/status" + mock_span = None + mock_api_key = "sk-test1234" + + error = ProxyException( + message="Token not found", + type=ProxyErrorTypes.token_not_found_in_db, + param="key", + code=401, + ) + + with patch( + "litellm.proxy.proxy_server.general_settings", + {"allow_requests_on_db_unavailable": False}, + ), patch.object(verbose_proxy_logger, "warning") as mock_warning: + try: + await handler._handle_authentication_error( + error, + mock_request, + mock_request_data, + mock_route, + mock_span, + mock_api_key, + ) + except Exception: + pass + + mock_warning.assert_called_once() + log_message = mock_warning.call_args[0][0] + log_extra = mock_warning.call_args[1].get("extra", {}) + + # Verify structured fields are in the log message + assert mock_route in log_message + assert "GET" in log_message + assert "sk-...1234" in log_message + + # Verify structured extra dict for log aggregation tools + assert log_extra["route"] == mock_route + assert log_extra["http_method"] == "GET" + assert log_extra["api_key"] == "sk-...1234" + assert log_extra["error_type"] == ProxyErrorTypes.token_not_found_in_db + + +@pytest.mark.asyncio +async def test_auth_error_log_handles_none_api_key(): + """ + When no API key is provided (None or empty), the log should show 'None' + instead of crashing. + """ + handler = UserAPIKeyAuthExceptionHandler() + + mock_request = MagicMock() + mock_request.method = "GET" + mock_request_data = {} + mock_route = "/test" + mock_span = None + + error = Exception("No api key passed in.") + + for empty_key in [None, ""]: + with patch( + "litellm.proxy.proxy_server.general_settings", + {"allow_requests_on_db_unavailable": False}, + ), patch.object(verbose_proxy_logger, "exception") as mock_exception: + try: + await handler._handle_authentication_error( + error, + mock_request, + mock_request_data, + mock_route, + mock_span, + empty_key, + ) + except Exception: + pass + + mock_exception.assert_called_once() + log_message = mock_exception.call_args[0][0] + assert "None" in log_message