From 3fadcd71553dcf02c76e465a17af34cca715e7ef Mon Sep 17 00:00:00 2001 From: yucheng-berri Date: Mon, 31 Aug 2026 18:19:40 -0700 Subject: [PATCH] fix(auth): quiet malformed virtual key rejections to stdout (#38838) * fix(auth): quiet malformed virtual key rejections to stdout Reduce noisy invalid-api-key error logs by classifying malformed virtual keys and routing their rejections to stdout as WARNING instead of stderr as ERROR. Suppressible via LITELLM_LOG=ERROR or log_client_error_tracebacks=true. Changes: - auth_utils: is_invalid_virtual_key_error() classifier and marker functions - auth_exception_handler: log invalid keys as WARNING to child logger before identity seeding and callbacks, escalate non-401 transforms to ERROR - user_api_key_auth: websocket early-raise WebSocketException(1008) to avoid double-logging at HTTP layer - _logging: child logger verbose_proxy_stdout_logger with no handler/level; LevelRoutingStreamHandler routes its WARNING records to stdout; handler setLevel in _turn_on_json() closes JSON config handler level leak - test_auth_exception_handler: new test case verifying malformed-key logs at WARNING with marker retention through transformations Fixes LIT-5362 * fix(auth): classify malformed-key 401 by raise-site marker, not message text Review round 1 (Greptile P2, veria Low): - Move the marker attribute name to litellm/constants.py per the shared sentinel convention - Stamp the marker on the malformed-key 401 where it is raised and classify only by it. Message text is caller-influenceable on other 401s (vector store ids, organization ids are interpolated into their messages), so a phrase match would let a request body demote an authorization failure to the quiet log path - Regression test: a 401 carrying the phrase but not the marker stays at ERROR on stderr --- litellm/_logging.py | 15 ++- litellm/constants.py | 6 + litellm/proxy/auth/auth_exception_handler.py | 103 +++++++++++------- litellm/proxy/auth/auth_utils.py | 38 +++++++ litellm/proxy/auth/user_api_key_auth.py | 14 ++- .../proxy/auth/test_auth_exception_handler.py | 36 +++++- 6 files changed, 162 insertions(+), 50 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index fbb35b72be2..9435562f890 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -264,13 +264,17 @@ def _plain_log_format(stdout: TextIO | None, stderr: TextIO | None) -> str: class LevelRoutingStreamHandler(logging.StreamHandler): - """Writes records below WARNING to stdout and WARNING and above to stderr. + """Writes records below WARNING and invalid-key warnings to stdout, others to stderr. Collectors that derive severity from the stream report every stderr line as an error. + Invalid-key warnings route to stdout so LITELLM_LOG=ERROR can suppress them. """ def emit(self, record: logging.LogRecord) -> None: - preferred: Final = sys.stdout if record.levelno < logging.WARNING else sys.stderr + is_stdout_record: Final = record.levelno < logging.WARNING or ( + record.levelno == logging.WARNING and record.name == verbose_proxy_stdout_logger.name + ) + preferred: Final = sys.stdout if is_stdout_record else sys.stderr if preferred is None or getattr(preferred, "closed", False): self.stream = sys.stderr # rebind-ok: fall back to the pre-fix stream rather than raising per record else: @@ -508,6 +512,9 @@ else: handler.setFormatter(formatter) verbose_proxy_logger = logging.getLogger("LiteLLM Proxy") +# Malformed virtual key rejections log through this child; LevelRoutingStreamHandler +# writes its WARNING records to stdout. It has no handler or level of its own. +verbose_proxy_stdout_logger: Final = verbose_proxy_logger.getChild("stdout") verbose_router_logger = logging.getLogger("LiteLLM Router") verbose_logger = logging.getLogger("LiteLLM") @@ -520,6 +527,7 @@ verbose_logger.addHandler(handler) # handlers (JSON mode, uvicorn log config, a host app's root handler). verbose_router_logger.addFilter(_stdout_truncation_filter) verbose_proxy_logger.addFilter(_stdout_truncation_filter) +verbose_proxy_stdout_logger.addFilter(_stdout_truncation_filter) verbose_logger.addFilter(_stdout_truncation_filter) @@ -683,6 +691,7 @@ def _turn_on_json(): - Adds a JSON formatter to all loggers """ handler: Final = LevelRoutingStreamHandler() + handler.setLevel(numeric_level) handler.setFormatter(JsonFormatter()) _initialize_loggers_with_handler(handler) # Set up exception handlers @@ -700,12 +709,14 @@ def _disable_debugging(): verbose_logger.disabled = True verbose_router_logger.disabled = True verbose_proxy_logger.disabled = True + verbose_proxy_stdout_logger.disabled = True def _enable_debugging(): verbose_logger.disabled = False verbose_router_logger.disabled = False verbose_proxy_logger.disabled = False + verbose_proxy_stdout_logger.disabled = False def print_verbose(print_statement): diff --git a/litellm/constants.py b/litellm/constants.py index 1c8a6dc5874..c482ab0e39a 100644 --- a/litellm/constants.py +++ b/litellm/constants.py @@ -1427,6 +1427,12 @@ DEFAULT_SOFT_BUDGET: Final = float( ) # by default all litellm proxy keys have a soft budget of 50.0 # makes it clear this is a rate limit error for a litellm virtual key RATE_LIMIT_ERROR_MESSAGE_FOR_VIRTUAL_KEY: Final = "LiteLLM Virtual Key user_api_key_hash" +# Prefix of the 401 raised when a submitted virtual key is not shaped like one. +INVALID_VIRTUAL_KEY_ERROR_MESSAGE: Final = "LiteLLM Virtual Key expected" +# Attribute stamped on that 401 at its raise site so log routing recognises it by +# provenance. Message text is caller-influenceable on other 401s, so it must not +# be used to classify. +INVALID_VIRTUAL_KEY_ERROR_MARKER: Final = "_litellm_invalid_virtual_key_error" # Python garbage collection threshold configuration # Format: "gen0,gen1,gen2" e.g., "1000,50,50" diff --git a/litellm/proxy/auth/auth_exception_handler.py b/litellm/proxy/auth/auth_exception_handler.py index a42187b3a44..64878a480a7 100644 --- a/litellm/proxy/auth/auth_exception_handler.py +++ b/litellm/proxy/auth/auth_exception_handler.py @@ -2,13 +2,14 @@ Handles Authentication Errors """ +import logging from collections.abc import Mapping from typing import TYPE_CHECKING, Any, Final from fastapi import HTTPException, Request, status import litellm -from litellm._logging import verbose_proxy_logger +from litellm._logging import verbose_proxy_logger, verbose_proxy_stdout_logger from litellm.constants import EMPTY_MAPPING from litellm.integrations.otel.runtime import seed_request_identity from litellm.litellm_core_utils.core_helpers import is_expected_client_error @@ -18,7 +19,11 @@ from litellm.proxy._types import ( ProxyException, UserAPIKeyAuth, ) -from litellm.proxy.auth.auth_utils import _get_request_ip_address +from litellm.proxy.auth.auth_utils import ( + _get_request_ip_address, + is_invalid_virtual_key_error, + mark_invalid_virtual_key_error, +) from litellm.proxy.db.exception_handler import PrismaDBExceptionHandler from litellm.types.services import ServiceTypes @@ -36,6 +41,41 @@ else: Span = Any +def _as_proxy_exception(e: Exception) -> ProxyException: + """Convert an authentication failure into the ProxyException the client receives.""" + if isinstance(e, litellm.BudgetExceededError): + return ProxyException( + message=e.message, + type=ProxyErrorTypes.budget_exceeded, + param=None, + code=getattr(e, "status_code", status.HTTP_429_TOO_MANY_REQUESTS), + ) + if isinstance(e, HTTPException): + return ProxyException( + message=getattr(e, "detail", f"Authentication Error({e})"), + type=ProxyErrorTypes.auth_error, + param=getattr(e, "param", "None"), + code=getattr(e, "status_code", status.HTTP_401_UNAUTHORIZED), + ) + if isinstance(e, ProxyException): + return e + if PrismaDBExceptionHandler.is_database_service_unavailable_error(e): + return ProxyException( + message=( + "Service Unavailable, the authentication database is temporarily unreachable. Please retry shortly." + ), + type=ProxyErrorTypes.no_db_connection, + param="None", + code=status.HTTP_503_SERVICE_UNAVAILABLE, + ) + return ProxyException( + message="Authentication Error, " + str(e), + type=ProxyErrorTypes.auth_error, + param=getattr(e, "param", "None"), + code=status.HTTP_401_UNAUTHORIZED, + ) + + def _with_requester_ip_address(request_data: dict[str, object], requester_ip: str | None) -> dict[str, object]: """Auth gate rejections are raised before `add_litellm_data_to_request` records the caller IP, so their failure logs would otherwise carry no IP nor key/user identity.""" @@ -110,16 +150,21 @@ class UserAPIKeyAuthExceptionHandler: request=request, use_x_forwarded_for=general_settings.get("use_x_forwarded_for") is True, ) - log_fn: Final = ( - verbose_proxy_logger.error - if is_expected_client_error(e) and not litellm.log_client_error_tracebacks - else verbose_proxy_logger.exception - ) - log_fn( + + # Log authentication failures before identity seeding and callbacks, so the log + # survives a raising callback pipeline. Classify and route malformed virtual-key + # rejections to WARNING on stdout (suppressible via LITELLM_LOG=ERROR). + log_extra: Final = {"requester_ip": requester_ip} + is_invalid_virtual_key: Final = is_invalid_virtual_key_error(e) + is_quiet_log: Final = is_invalid_virtual_key and not litellm.log_client_error_tracebacks + logger: Final = verbose_proxy_stdout_logger if is_quiet_log else verbose_proxy_logger + logger.log( + logging.WARNING if is_quiet_log else logging.ERROR, "litellm.proxy.proxy_server.user_api_key_auth(): Exception occured - %s\nRequester IP Address:%s", e, requester_ip, - extra={"requester_ip": requester_ip}, + exc_info=True if litellm.log_client_error_tracebacks or not is_expected_client_error(e) else None, + extra=log_extra, ) # Log this exception to OTEL, Datadog etc. Reuse the identity resolved @@ -167,35 +212,13 @@ class UserAPIKeyAuthExceptionHandler: if transformed_exception is not None: e = transformed_exception - if isinstance(e, litellm.BudgetExceededError): - raise ProxyException( - message=e.message, - type=ProxyErrorTypes.budget_exceeded, - param=None, - code=getattr(e, "status_code", status.HTTP_429_TOO_MANY_REQUESTS), + final_exception: Final = mark_invalid_virtual_key_error(_as_proxy_exception(e), is_invalid_virtual_key) + # If a quiet-logged malformed-key transform yields non-401, escalate to ERROR + if is_quiet_log and str(final_exception.code) != str(status.HTTP_401_UNAUTHORIZED): + verbose_proxy_logger.error( + "litellm.proxy.proxy_server.user_api_key_auth(): Exception occured - %s\nRequester IP Address:%s", + final_exception, + requester_ip, + extra=log_extra, ) - if isinstance(e, HTTPException): - raise ProxyException( - message=getattr(e, "detail", f"Authentication Error({e})"), - type=ProxyErrorTypes.auth_error, - param=getattr(e, "param", "None"), - code=getattr(e, "status_code", status.HTTP_401_UNAUTHORIZED), - ) - elif isinstance(e, ProxyException): - raise e - if PrismaDBExceptionHandler.is_database_service_unavailable_error(e): - raise ProxyException( - message=( - "Service Unavailable, the authentication database is " - "temporarily unreachable. Please retry shortly." - ), - type=ProxyErrorTypes.no_db_connection, - param="None", - code=status.HTTP_503_SERVICE_UNAVAILABLE, - ) - raise ProxyException( - message="Authentication Error, " + str(e), - type=ProxyErrorTypes.auth_error, - param=getattr(e, "param", "None"), - code=status.HTTP_401_UNAUTHORIZED, - ) + raise final_exception diff --git a/litellm/proxy/auth/auth_utils.py b/litellm/proxy/auth/auth_utils.py index 9b1a6ba5aa7..83ee10b8108 100644 --- a/litellm/proxy/auth/auth_utils.py +++ b/litellm/proxy/auth/auth_utils.py @@ -15,6 +15,7 @@ from litellm._logging import verbose_proxy_logger from litellm.constants import ( BATCH_ENQUEUED_TOKEN_LIMIT_METADATA_KEY, EMPTY_MAPPING, + INVALID_VIRTUAL_KEY_ERROR_MARKER, MINIMUM_CUSTOM_KEY_LENGTH, STANDARD_CUSTOMER_ID_HEADERS, ) @@ -34,6 +35,43 @@ from litellm.types.router import CONFIGURABLE_CLIENTSIDE_AUTH_PARAMS from litellm.types.utils import CustomPricingLiteLLMParams +def is_invalid_virtual_key_error(exception: BaseException | None) -> bool: + """True when an authentication error rejects a malformed virtual key. + + Classifies only by the marker stamped where that 401 is raised. Message + content is never inspected: other 401s interpolate caller-supplied values + (vector store ids, organization ids) into their messages, so a phrase + match would let a request body demote an authorization failure to the + quiet log path. + """ + if not isinstance(exception, (HTTPException, ProxyException)): + return False + + code: Final[object] = getattr(exception, "code", None) + status_code: Final[object] = code if code is not None else getattr(exception, "status_code", None) + if str(status_code) != str(status.HTTP_401_UNAUTHORIZED): + return False + + return getattr(exception, INVALID_VIRTUAL_KEY_ERROR_MARKER, False) is True + + +def mark_invalid_virtual_key_error(exception: ProxyException, is_invalid_virtual_key: bool) -> ProxyException: + """Return an independently marked malformed-key exception after callback transformations.""" + if not is_invalid_virtual_key or str(exception.code) != str(status.HTTP_401_UNAUTHORIZED): + return exception + marked_exception: Final = ProxyException( + message=exception.message, + type=exception.type, + param=exception.param, + code=exception.code, + headers=exception.headers.copy(), + openai_code=None if exception.openai_code is None else str(exception.openai_code), + provider_specific_fields=exception.provider_specific_fields, + ) + setattr(marked_exception, INVALID_VIRTUAL_KEY_ERROR_MARKER, True) + return marked_exception + + def _get_request_ip_address(request: Request, use_x_forwarded_for: bool | None = False) -> str | None: client_ip = None if use_x_forwarded_for is True and "x-forwarded-for" in request.headers: diff --git a/litellm/proxy/auth/user_api_key_auth.py b/litellm/proxy/auth/user_api_key_auth.py index e92d090a2fb..5fb6dad0cd7 100644 --- a/litellm/proxy/auth/user_api_key_auth.py +++ b/litellm/proxy/auth/user_api_key_auth.py @@ -19,12 +19,15 @@ import fastapi import orjson from fastapi import HTTPException, Request, WebSocket, status from fastapi.security.api_key import APIKeyHeader +from starlette.exceptions import WebSocketException import litellm from litellm._logging import verbose_logger, verbose_proxy_logger from litellm._service_logger import ServiceLogging from litellm.constants import ( GLOBAL_PROXY_SPEND_CACHE_KEY, + INVALID_VIRTUAL_KEY_ERROR_MARKER, + INVALID_VIRTUAL_KEY_ERROR_MESSAGE, LITELLM_PROXY_BUDGET_NAME, LITELLM_PROXY_MASTER_KEY_ALIAS, ) @@ -65,6 +68,7 @@ from litellm.proxy.auth.auth_utils import ( get_model_from_request, get_request_route, get_request_route_template, + is_invalid_virtual_key_error, iter_request_fallback_targets, normalize_request_route, pre_db_read_auth_checks, @@ -539,6 +543,8 @@ async def user_api_key_auth_websocket(websocket: WebSocket): try: return await user_api_key_auth(request=request, api_key=f"Bearer {api_key}") except Exception as e: + if is_invalid_virtual_key_error(e): + raise WebSocketException(code=status.WS_1008_POLICY_VIOLATION) verbose_proxy_logger.exception(e) await websocket.close(code=status.WS_1008_POLICY_VIOLATION) raise HTTPException(status_code=403, detail=str(e)) @@ -1867,13 +1873,17 @@ async def _user_api_key_auth_builder( _masked_key: Final = f"{api_key[:4]}****{api_key[-4:]}" if len(api_key) > 8 else "****" if not api_key.startswith("sk-"): _hint = _JWT_AUTH_DISABLED_HINT if not enable_jwt_auth and JWTHandler.is_jwt(token=api_key) else "" - raise HTTPException( + _malformed_key_error = HTTPException( status_code=status.HTTP_401_UNAUTHORIZED, detail=( - f"LiteLLM Virtual Key expected. Received={_masked_key}, " + f"{INVALID_VIRTUAL_KEY_ERROR_MESSAGE}. Received={_masked_key}, " f"expected to start with 'sk-'.{_hint}" ), ) # prevent token hashes from being used + # Stamp provenance here so log routing classifies this 401 by + # where it was raised, never by its message text. + setattr(_malformed_key_error, INVALID_VIRTUAL_KEY_ERROR_MARKER, True) + raise _malformed_key_error else: verbose_logger.warning( "litellm.proxy.proxy_server.user_api_key_auth(): Warning - Key is not a string. Got type={}".format( 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 90b3b29d919..90be51cfa5b 100644 --- a/tests/test_litellm/proxy/auth/test_auth_exception_handler.py +++ b/tests/test_litellm/proxy/auth/test_auth_exception_handler.py @@ -26,6 +26,7 @@ from prisma.errors import ( from litellm._logging import verbose_proxy_logger +from litellm.constants import INVALID_VIRTUAL_KEY_ERROR_MARKER from litellm.exceptions import BudgetExceededError from litellm.proxy._types import ProxyErrorTypes, ProxyException, UserAPIKeyAuth from litellm.proxy.auth.auth_exception_handler import UserAPIKeyAuthExceptionHandler @@ -703,23 +704,43 @@ async def test_auth_failure_ip_stamp_does_not_mutate_callers_request_data(): assert request_data == {"model": "gpt-4o"} +def _marked_malformed_key_error() -> HTTPException: + """Build the malformed-key 401 as its raise site does: marker stamped on it.""" + error = HTTPException(status_code=401, detail="LiteLLM Virtual Key expected. Received=test") + setattr(error, INVALID_VIRTUAL_KEY_ERROR_MARKER, True) + return error + + @pytest.mark.asyncio @pytest.mark.parametrize( - "auth_error,expect_traceback", + "auth_error,expect_traceback,expect_level", [ pytest.param( ProxyException( message="Authentication Error", type=ProxyErrorTypes.auth_error, param=None, code=401 ), False, + "ERROR", id="expected_401_no_traceback", ), - pytest.param(ValueError("unexpected internal error"), True, id="unexpected_error_keeps_traceback"), + pytest.param(ValueError("unexpected internal error"), True, "ERROR", id="unexpected_error_keeps_traceback"), + pytest.param( + _marked_malformed_key_error(), + False, + "WARNING", + id="malformed_virtual_key_warning_no_traceback", + ), + pytest.param( + HTTPException(status_code=401, detail="LiteLLM Virtual Key expected. Received=test"), + False, + "ERROR", + id="phrase_without_marker_stays_loud", + ), ], ) -async def test_handle_authentication_error_traceback_only_for_unexpected_errors(auth_error, expect_traceback, caplog): +async def test_handle_authentication_error_traceback_only_for_unexpected_errors(auth_error, expect_traceback, expect_level, caplog): """Regression for LIT-6043: expected 4xx auth rejections must not format a - traceback via logger.exception; unexpected errors must keep it.""" + traceback via logger.exception; malformed virtual keys log at WARNING.""" handler = UserAPIKeyAuthExceptionHandler() with ( @@ -740,8 +761,8 @@ async def test_handle_authentication_error_traceback_only_for_unexpected_errors( try: try: raise auth_error - except (ProxyException, ValueError) as caught: - with caplog.at_level("ERROR", logger="LiteLLM Proxy"), pytest.raises(ProxyException): + except (ProxyException, ValueError, HTTPException) as caught: + with caplog.at_level(expect_level, logger="LiteLLM Proxy"), pytest.raises((ProxyException, HTTPException)): await handler._handle_authentication_error( caught, MagicMock(), @@ -756,3 +777,6 @@ async def test_handle_authentication_error_traceback_only_for_unexpected_errors( records = [r for r in caplog.records if "user_api_key_auth(): Exception occured" in r.getMessage()] assert len(records) == 1 assert (records[0].exc_info is not None) is expect_traceback + assert records[0].levelname == expect_level + expected_logger_name = "LiteLLM Proxy.stdout" if expect_level == "WARNING" else "LiteLLM Proxy" + assert records[0].name == expected_logger_name