From 1a1d6ce8043aeca4b2fc119d9f71d14c81b502db Mon Sep 17 00:00:00 2001 From: Yucheng Zhu Date: Fri, 28 Aug 2026 15:55:29 -0700 Subject: [PATCH] fix(proxy): route invalid virtual key logs to stdout --- litellm/_logging.py | 28 +- litellm/proxy/auth/auth_exception_handler.py | 62 +++-- litellm/proxy/auth/auth_utils.py | 37 +++ litellm/proxy/auth/user_api_key_auth.py | 7 +- .../test_user_api_key_auth.py | 38 +++ .../proxy/auth/test_auth_exception_handler.py | 242 +++++++++++++++++- tests/test_litellm/test_logging.py | 119 ++++++++- 7 files changed, 481 insertions(+), 52 deletions(-) diff --git a/litellm/_logging.py b/litellm/_logging.py index fbb35b72be2..c2e540dd714 100644 --- a/litellm/_logging.py +++ b/litellm/_logging.py @@ -264,13 +264,16 @@ 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. Collectors that derive severity from the stream report every stderr line as an error. """ 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: @@ -507,19 +510,30 @@ else: handler.setFormatter(formatter) -verbose_proxy_logger = logging.getLogger("LiteLLM Proxy") -verbose_router_logger = logging.getLogger("LiteLLM Router") -verbose_logger = logging.getLogger("LiteLLM") +verbose_proxy_logger: Final = logging.getLogger("LiteLLM Proxy") +verbose_proxy_stdout_logger: Final = verbose_proxy_logger.getChild("stdout") +verbose_router_logger: Final = logging.getLogger("LiteLLM Router") +verbose_logger: Final = logging.getLogger("LiteLLM") + +verbose_proxy_stdout_handler: Final = LevelRoutingStreamHandler() +verbose_proxy_stdout_handler.setLevel(logging.WARNING) +verbose_proxy_stdout_handler.setFormatter(handler.formatter) +verbose_proxy_stdout_handler.addFilter(_secret_filter) +verbose_proxy_stdout_handler.addFilter(_correlation_filter) # Add the handler to the loggers verbose_router_logger.addHandler(handler) verbose_proxy_logger.addHandler(handler) +verbose_proxy_stdout_logger.setLevel(logging.WARNING) +verbose_proxy_stdout_logger.addHandler(verbose_proxy_stdout_handler) +verbose_proxy_stdout_logger.propagate = False verbose_logger.addHandler(handler) # Filters attached to the logger, not the handler, survive callers swapping in their own # 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) @@ -578,6 +592,7 @@ ALL_LOGGERS: Final = [ verbose_logger, verbose_router_logger, verbose_proxy_logger, + verbose_proxy_stdout_logger, ] @@ -685,6 +700,7 @@ def _turn_on_json(): handler: Final = LevelRoutingStreamHandler() handler.setFormatter(JsonFormatter()) _initialize_loggers_with_handler(handler) + verbose_proxy_stdout_logger.setLevel(logging.WARNING) # Set up exception handlers _setup_json_exception_handlers(JsonFormatter()) @@ -700,12 +716,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/proxy/auth/auth_exception_handler.py b/litellm/proxy/auth/auth_exception_handler.py index a42187b3a44..ddb46c8821d 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 @@ -110,17 +115,8 @@ 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( - "litellm.proxy.proxy_server.user_api_key_auth(): Exception occured - %s\nRequester IP Address:%s", - e, - requester_ip, - extra={"requester_ip": requester_ip}, - ) + original_exception: Final = e + is_invalid_virtual_key: Final = is_invalid_virtual_key_error(e) # Log this exception to OTEL, Datadog etc. Reuse the identity resolved # before the failure (team alias/id, metadata, user) so the failed span @@ -158,7 +154,7 @@ class UserAPIKeyAuthExceptionHandler: # Allow callbacks to transform the error response transformed_exception: Final = await proxy_logging_obj.post_call_failure_hook( request_data=_with_requester_ip_address(request_data, requester_ip), - original_exception=e, + original_exception=original_exception, user_api_key_dict=user_api_key_dict, error_type=ProxyErrorTypes.auth_error, route=route, @@ -167,24 +163,25 @@ class UserAPIKeyAuthExceptionHandler: if transformed_exception is not None: e = transformed_exception + proxy_exception: Final if isinstance(e, litellm.BudgetExceededError): - raise ProxyException( + proxy_exception = 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): - raise ProxyException( + elif isinstance(e, HTTPException): + proxy_exception = 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( + proxy_exception = e + elif PrismaDBExceptionHandler.is_database_service_unavailable_error(e): + proxy_exception = ProxyException( message=( "Service Unavailable, the authentication database is " "temporarily unreachable. Please retry shortly." @@ -193,9 +190,24 @@ class UserAPIKeyAuthExceptionHandler: 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, + else: + proxy_exception = ProxyException( + message="Authentication Error, " + str(e), + type=ProxyErrorTypes.auth_error, + param=getattr(e, "param", "None"), + code=status.HTTP_401_UNAUTHORIZED, + ) + final_exception: Final = mark_invalid_virtual_key_error(proxy_exception, is_invalid_virtual_key) + is_quiet_log: Final = ( + is_invalid_virtual_key_error(final_exception) 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", + final_exception, + requester_ip, + exc_info=not (is_expected_client_error(original_exception) and not litellm.log_client_error_tracebacks), + extra={"requester_ip": requester_ip}, + ) + raise final_exception diff --git a/litellm/proxy/auth/auth_utils.py b/litellm/proxy/auth/auth_utils.py index 9b1a6ba5aa7..ccb8e350892 100644 --- a/litellm/proxy/auth/auth_utils.py +++ b/litellm/proxy/auth/auth_utils.py @@ -33,6 +33,9 @@ from litellm.types.passthrough_endpoints.pass_through_endpoints import ( from litellm.types.router import CONFIGURABLE_CLIENTSIDE_AUTH_PARAMS from litellm.types.utils import CustomPricingLiteLLMParams +INVALID_VIRTUAL_KEY_ERROR_MESSAGE: Final = "LiteLLM Virtual Key expected" +_INVALID_VIRTUAL_KEY_ERROR_MARKER: Final = "_litellm_invalid_virtual_key_error" + def _get_request_ip_address(request: Request, use_x_forwarded_for: bool | None = False) -> str | None: client_ip = None @@ -46,6 +49,40 @@ def _get_request_ip_address(request: Request, use_x_forwarded_for: bool | None = return client_ip +def is_invalid_virtual_key_error(exception: BaseException | None) -> bool: + """True when an authentication error rejects a malformed virtual key.""" + 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 + + if getattr(exception, _INVALID_VIRTUAL_KEY_ERROR_MARKER, False) is True: + return True + + message: Final = getattr(exception, "detail", None) or getattr(exception, "message", "") + return INVALID_VIRTUAL_KEY_ERROR_MESSAGE in str(message) + + +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=exception.openai_code, + provider_specific_fields=exception.provider_specific_fields, + ) + setattr(marked_exception, _INVALID_VIRTUAL_KEY_ERROR_MARKER, True) + return marked_exception + + def _check_valid_ip( allowed_ips: list[str] | None, request: Request, diff --git a/litellm/proxy/auth/user_api_key_auth.py b/litellm/proxy/auth/user_api_key_auth.py index e92d090a2fb..add6b2bd8a4 100644 --- a/litellm/proxy/auth/user_api_key_auth.py +++ b/litellm/proxy/auth/user_api_key_auth.py @@ -19,6 +19,7 @@ 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 @@ -60,11 +61,13 @@ from litellm.proxy.auth.auth_checks import ( from litellm.proxy.auth.auth_exception_handler import UserAPIKeyAuthExceptionHandler from litellm.proxy.auth.auth_method import AuthMethod from litellm.proxy.auth.auth_utils import ( + INVALID_VIRTUAL_KEY_ERROR_MESSAGE, abbreviate_api_key, get_end_user_id_from_request_body, 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 +542,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)) @@ -1870,7 +1875,7 @@ async def _user_api_key_auth_builder( raise 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 diff --git a/tests/proxy_unit_tests/test_user_api_key_auth.py b/tests/proxy_unit_tests/test_user_api_key_auth.py index 0cdf3500d50..66c3d62f5c4 100644 --- a/tests/proxy_unit_tests/test_user_api_key_auth.py +++ b/tests/proxy_unit_tests/test_user_api_key_auth.py @@ -874,6 +874,44 @@ async def test_user_api_key_auth_websocket(): assert mock_user_api_key_auth.call_args.kwargs["api_key"] == "Bearer some_api_key" +@pytest.mark.asyncio +async def test_user_api_key_auth_websocket_skips_duplicate_invalid_key_log(): + from litellm.proxy._types import ProxyException + from litellm.proxy.auth.auth_utils import mark_invalid_virtual_key_error + from litellm.proxy.auth.user_api_key_auth import WebSocketException, user_api_key_auth_websocket + + mock_websocket = MagicMock(spec=WebSocket) + mock_websocket.query_params = {"model": "some_model"} + mock_websocket.headers = {"authorization": "Bearer undefined"} + mock_websocket.scope = {"headers": [(b"authorization", b"Bearer undefined")]} + mock_websocket.url = URL(url="/v1/responses") + transformed_invalid_virtual_key = mark_invalid_virtual_key_error( + ProxyException( + message="Please authenticate again", + type="auth_error", + param="None", + code=status.HTTP_401_UNAUTHORIZED, + ), + True, + ) + + with ( + patch( + "litellm.proxy.auth.user_api_key_auth.user_api_key_auth", + side_effect=transformed_invalid_virtual_key, + autospec=True, + ), + patch("litellm.proxy.auth.user_api_key_auth.verbose_proxy_logger.exception") as exception_log, + pytest.raises(WebSocketException) as exc_info, + ): + await user_api_key_auth_websocket(mock_websocket) + + assert exc_info.value.code == status.WS_1008_POLICY_VIOLATION + assert exc_info.value.reason == "" + exception_log.assert_not_called() + mock_websocket.close.assert_not_called() + + @pytest.mark.asyncio async def test_user_api_key_auth_websocket_carries_asgi_path(): """ 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..cf34e35f65a 100644 --- a/tests/test_litellm/proxy/auth/test_auth_exception_handler.py +++ b/tests/test_litellm/proxy/auth/test_auth_exception_handler.py @@ -1,5 +1,6 @@ import asyncio import json +import logging from unittest.mock import AsyncMock, MagicMock, patch import httpx @@ -24,8 +25,7 @@ from prisma.errors import ( UniqueViolationError, ) - -from litellm._logging import verbose_proxy_logger +from litellm._logging import verbose_proxy_logger, verbose_proxy_stdout_logger from litellm.exceptions import BudgetExceededError from litellm.proxy._types import ProxyErrorTypes, ProxyException, UserAPIKeyAuth from litellm.proxy.auth.auth_exception_handler import UserAPIKeyAuthExceptionHandler @@ -335,9 +335,7 @@ async def test_handle_authentication_error_budget_exceeded(): # Test with budget exceeded error from litellm.exceptions import BudgetExceededError - budget_error = BudgetExceededError( - message="Budget exceeded", current_cost=100, max_budget=100 - ) + budget_error = BudgetExceededError(message="Budget exceeded", current_cost=100, max_budget=100) with pytest.raises(ProxyException) as exc_info: await handler._handle_authentication_error( @@ -705,19 +703,79 @@ async def test_auth_failure_ip_stamp_does_not_mutate_callers_request_data(): @pytest.mark.asyncio @pytest.mark.parametrize( - "auth_error,expect_traceback", + "auth_error,expected_level,expect_traceback,log_client_error_tracebacks", [ pytest.param( - ProxyException( - message="Authentication Error", type=ProxyErrorTypes.auth_error, param=None, code=401 + HTTPException( + status_code=status.HTTP_401_UNAUTHORIZED, + detail="LiteLLM Virtual Key expected. Received=unde****ined, expected to start with 'sk-'.", ), + logging.WARNING, False, - id="expected_401_no_traceback", + False, + id="invalid_virtual_key_logs_at_warning_without_traceback", + ), + pytest.param( + HTTPException( + status_code=status.HTTP_401_UNAUTHORIZED, + detail="LiteLLM Virtual Key expected. Received=unde****ined, expected to start with 'sk-'.", + ), + logging.ERROR, + True, + True, + id="invalid_virtual_key_keeps_traceback_opt_in", + ), + pytest.param( + HTTPException( + status_code=status.HTTP_401_UNAUTHORIZED, + detail="Authentication Error", + ), + logging.ERROR, + False, + False, + id="other_http_401_keeps_error_level_without_traceback", + ), + pytest.param( + ProxyException( + message="LiteLLM Virtual Key expected", + type=ProxyErrorTypes.auth_error, + param=None, + code=401, + ), + logging.WARNING, + False, + False, + id="custom_auth_invalid_virtual_key_logs_at_warning_without_traceback", + ), + pytest.param( + ProxyException(message="Authentication Error", type=ProxyErrorTypes.auth_error, param=None, code=401), + logging.ERROR, + False, + False, + id="other_expected_401_keeps_error_level_without_traceback", + ), + pytest.param( + ValueError("unexpected internal error"), + logging.ERROR, + True, + False, + id="unexpected_error_keeps_traceback", + ), + pytest.param( + HTTPException( + status_code=status.HTTP_503_SERVICE_UNAVAILABLE, + detail="Authentication database unavailable", + ), + logging.ERROR, + True, + False, + id="server_error_keeps_traceback", ), - pytest.param(ValueError("unexpected internal error"), True, id="unexpected_error_keeps_traceback"), ], ) -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, expected_level, expect_traceback, log_client_error_tracebacks, caplog +): """Regression for LIT-6043: expected 4xx auth rejections must not format a traceback via logger.exception; unexpected errors must keep it.""" handler = UserAPIKeyAuthExceptionHandler() @@ -731,17 +789,22 @@ async def test_handle_authentication_error_traceback_only_for_unexpected_errors( patch( # test-quality-ok: handler reads proxy_server globals at call time "litellm.proxy.auth.auth_exception_handler.seed_request_identity", ), + patch( # test-quality-ok: handler reads this global flag at call time + "litellm.proxy.auth.auth_exception_handler.litellm.log_client_error_tracebacks", + log_client_error_tracebacks, + ), patch( # test-quality-ok: handler reads proxy_server globals at call time "litellm.proxy.proxy_server.general_settings", {"allow_requests_on_db_unavailable": False}, ), ): verbose_proxy_logger.propagate = True + verbose_proxy_stdout_logger.propagate = True try: try: raise auth_error - except (ProxyException, ValueError) as caught: - with caplog.at_level("ERROR", logger="LiteLLM Proxy"), pytest.raises(ProxyException): + except (HTTPException, ProxyException, ValueError) as caught: + with caplog.at_level(logging.DEBUG), pytest.raises(ProxyException): await handler._handle_authentication_error( caught, MagicMock(), @@ -752,7 +815,158 @@ async def test_handle_authentication_error_traceback_only_for_unexpected_errors( ) finally: verbose_proxy_logger.propagate = False + verbose_proxy_stdout_logger.propagate = False 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].levelno == expected_level + assert bool(records[0].exc_info) is expect_traceback + assert records[0].name == ( + verbose_proxy_stdout_logger.name + if expected_level == logging.WARNING and not log_client_error_tracebacks + else verbose_proxy_logger.name + ) + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "transformed_exception", + [ + HTTPException(status_code=status.HTTP_401_UNAUTHORIZED, detail="Please authenticate again"), + ProxyException( + message="Please authenticate again", + type=ProxyErrorTypes.auth_error, + param=None, + code=status.HTTP_401_UNAUTHORIZED, + ), + ], +) +async def test_handle_authentication_error_preserves_invalid_virtual_key_marker_after_callback_transform( + caplog, + transformed_exception, +): + handler = UserAPIKeyAuthExceptionHandler() + original_exception = HTTPException( + status_code=status.HTTP_401_UNAUTHORIZED, + detail="LiteLLM Virtual Key expected. Received=unde****ined, expected to start with 'sk-'.", + ) + + with ( + patch( + "litellm.proxy.proxy_server.proxy_logging_obj.post_call_failure_hook", + new_callable=AsyncMock, + return_value=transformed_exception, + ), + patch("litellm.proxy.auth.auth_exception_handler.seed_request_identity"), + patch("litellm.proxy.proxy_server.general_settings", {"allow_requests_on_db_unavailable": False}), + ): + verbose_proxy_stdout_logger.propagate = True + try: + with pytest.raises(ProxyException) as exc_info: + await handler._handle_authentication_error( + original_exception, + MagicMock(), + {}, + "/v1/chat/completions", + None, + "undefined", + ) + finally: + verbose_proxy_stdout_logger.propagate = False + + records = [r for r in caplog.records if "user_api_key_auth(): Exception occured" in r.getMessage()] + assert len(records) == 1 + assert records[0].name == verbose_proxy_stdout_logger.name + assert records[0].levelno == logging.WARNING + assert exc_info.value.message == "Please authenticate again" + assert getattr(exc_info.value, "_litellm_invalid_virtual_key_error") is True + if isinstance(transformed_exception, ProxyException): + assert not hasattr(transformed_exception, "_litellm_invalid_virtual_key_error") + + +@pytest.mark.asyncio +async def test_handle_authentication_error_keeps_unexpected_source_traceback_after_callback_4xx( + caplog, +): + handler = UserAPIKeyAuthExceptionHandler() + + with ( + patch( + "litellm.proxy.proxy_server.proxy_logging_obj.post_call_failure_hook", + new_callable=AsyncMock, + return_value=HTTPException( + status_code=status.HTTP_401_UNAUTHORIZED, + detail="Please authenticate again", + ), + ), + patch("litellm.proxy.auth.auth_exception_handler.seed_request_identity"), + patch("litellm.proxy.proxy_server.general_settings", {"allow_requests_on_db_unavailable": False}), + ): + verbose_proxy_logger.propagate = True + try: + with pytest.raises(ProxyException) as exc_info: + await handler._handle_authentication_error( + ValueError("unexpected internal error"), + MagicMock(), + {}, + "/v1/chat/completions", + None, + "sk-bad-key", + ) + finally: + verbose_proxy_logger.propagate = False + + records = [r for r in caplog.records if "user_api_key_auth(): Exception occured" in r.getMessage()] + assert len(records) == 1 + assert records[0].name == verbose_proxy_logger.name + assert records[0].levelno == logging.ERROR + assert records[0].exc_info is not None + assert "Please authenticate again" in records[0].getMessage() + assert exc_info.value.code == str(status.HTTP_401_UNAUTHORIZED) + + +@pytest.mark.asyncio +async def test_handle_authentication_error_does_not_preserve_invalid_virtual_key_marker_for_callback_503( + caplog, +): + handler = UserAPIKeyAuthExceptionHandler() + original_exception = HTTPException( + status_code=status.HTTP_401_UNAUTHORIZED, + detail="LiteLLM Virtual Key expected. Received=unde****ined, expected to start with 'sk-'.", + ) + transformed_exception = HTTPException( + status_code=status.HTTP_503_SERVICE_UNAVAILABLE, + detail="Authentication service temporarily unavailable", + ) + + with ( + patch( + "litellm.proxy.proxy_server.proxy_logging_obj.post_call_failure_hook", + new_callable=AsyncMock, + return_value=transformed_exception, + ), + patch("litellm.proxy.auth.auth_exception_handler.seed_request_identity"), + patch("litellm.proxy.proxy_server.general_settings", {"allow_requests_on_db_unavailable": False}), + ): + verbose_proxy_logger.propagate = True + try: + with pytest.raises(ProxyException) as exc_info: + await handler._handle_authentication_error( + original_exception, + MagicMock(), + {}, + "/v1/chat/completions", + None, + "undefined", + ) + finally: + verbose_proxy_logger.propagate = False + + records = [r for r in caplog.records if "user_api_key_auth(): Exception occured" in r.getMessage()] + assert len(records) == 1 + assert records[0].name == verbose_proxy_logger.name + assert records[0].levelno == logging.ERROR + assert records[0].exc_info is not None + assert "Authentication service temporarily unavailable" in records[0].getMessage() + assert exc_info.value.code == str(status.HTTP_503_SERVICE_UNAVAILABLE) + assert not hasattr(exc_info.value, "_litellm_invalid_virtual_key_error") diff --git a/tests/test_litellm/test_logging.py b/tests/test_litellm/test_logging.py index 087a1c8b3ad..680dd2015c4 100644 --- a/tests/test_litellm/test_logging.py +++ b/tests/test_litellm/test_logging.py @@ -1,15 +1,15 @@ import ast import asyncio import json +import logging import re import sys +from io import StringIO from pathlib import Path from typing import List import pytest -import logging - import litellm from litellm._logging import ( _COLOR_LOG_FORMAT, @@ -32,6 +32,7 @@ from litellm._logging import ( trace_id_var, verbose_logger, verbose_proxy_logger, + verbose_proxy_stdout_logger, verbose_router_logger, ) from litellm.constants import LITELLM_TRUNCATED_PAYLOAD_FIELD @@ -78,6 +79,21 @@ def test_json_mode_emits_one_record_per_logger(capfd): assert "timestamp" in obj, "`timestamp` key missing" +def test_json_mode_routes_invalid_key_record_once_to_stdout(capfd): + _turn_on_json() + + verbose_proxy_stdout_logger.warning("invalid virtual key") + + out, err = capfd.readouterr() + assert [raw for raw in err.splitlines() if raw.strip()] == [] + lines = [raw for raw in out.splitlines() if raw.strip()] + assert len(lines) == 1, f"got {len(lines)} lines, want 1: {lines!r}" + + record = json.loads(lines[0]) + assert record["message"] == "invalid virtual key" + assert record["component"] == verbose_proxy_stdout_logger.name + + def test_json_formatter_parses_embedded_json_message(): """ Test that JsonFormatter parses embedded JSON in the message field and promotes @@ -845,32 +861,121 @@ class _FakeStream: return self._tty -def test_records_below_warning_go_to_stdout_and_the_rest_to_stderr(capsys): - logger = logging.getLogger("test_level_routing") +def test_invalid_key_warning_routes_as_json_to_stdout(capsys): + logger = logging.getLogger("LiteLLM Proxy.stdout") + original_handlers = logger.handlers[:] + original_propagate = logger.propagate + original_level = logger.level logger.handlers.clear() logger.propagate = False logger.setLevel(logging.DEBUG) handler = LevelRoutingStreamHandler() + handler.setFormatter(JsonFormatter()) + logger.addHandler(handler) + + try: + logger.warning("invalid virtual key") + finally: + logger.handlers = original_handlers + logger.propagate = original_propagate + logger.setLevel(original_level) + + out, err = capsys.readouterr() + assert err == "" + log_record = json.loads(out) + assert log_record["message"] == "invalid virtual key" + assert log_record["level"] == "WARNING" + + +def test_records_below_warning_and_invalid_key_warnings_go_to_stdout(capsys): + logger = logging.getLogger("test_level_routing") + invalid_key_logger = logging.getLogger("LiteLLM Proxy.stdout") + original_handlers = logger.handlers[:] + original_propagate = logger.propagate + original_level = logger.level + original_invalid_key_handlers = invalid_key_logger.handlers[:] + original_invalid_key_propagate = invalid_key_logger.propagate + original_invalid_key_level = invalid_key_logger.level + logger.handlers.clear() + logger.propagate = False + logger.setLevel(logging.DEBUG) + invalid_key_logger.handlers.clear() + invalid_key_logger.propagate = False + invalid_key_logger.setLevel(logging.DEBUG) + handler = LevelRoutingStreamHandler() handler.setFormatter(logging.Formatter("%(levelname)s %(message)s")) logger.addHandler(handler) + invalid_key_logger.addHandler(handler) try: logger.debug("d") logger.info("i") logger.warning("w") + invalid_key_logger.warning("invalid-key-warning") logger.error("e") logger.critical("c") finally: - logger.handlers.clear() + logger.handlers = original_handlers + logger.propagate = original_propagate + logger.setLevel(original_level) + invalid_key_logger.handlers = original_invalid_key_handlers + invalid_key_logger.propagate = original_invalid_key_propagate + invalid_key_logger.setLevel(original_invalid_key_level) out, err = capsys.readouterr() - assert out.splitlines() == ["DEBUG d", "INFO i"] + assert out.splitlines() == ["DEBUG d", "INFO i", "WARNING invalid-key-warning"] assert err.splitlines() == ["WARNING w", "ERROR e", "CRITICAL c"] def test_verbose_loggers_route_records_by_level(): - for lg in (verbose_logger, verbose_router_logger, verbose_proxy_logger): + for lg in (verbose_logger, verbose_router_logger, verbose_proxy_logger, verbose_proxy_stdout_logger): assert any(isinstance(h, LevelRoutingStreamHandler) for h in lg.handlers), lg.name + assert verbose_proxy_stdout_logger.level == logging.WARNING + assert verbose_proxy_stdout_logger.handlers[0].level == logging.WARNING + + +def test_invalid_virtual_key_record_does_not_propagate_to_root_handler(): + root_logger = logging.getLogger() + root_stream = StringIO() + root_handler = logging.StreamHandler(root_stream) + root_handler.setFormatter(logging.Formatter("ROOT %(levelname)s %(message)s")) + root_logger.addHandler(root_handler) + + try: + verbose_proxy_stdout_logger.warning("invalid virtual key") + finally: + root_logger.removeHandler(root_handler) + + assert root_stream.getvalue() == "" + + +def test_turn_on_json_preserves_invalid_key_warning_visibility(monkeypatch, capfd): + monkeypatch.setenv("LITELLM_LOG", "ERROR") + _turn_on_json() + + verbose_proxy_stdout_logger.warning("invalid virtual key") + + out, err = capfd.readouterr() + assert [raw for raw in err.splitlines() if raw.strip()] == [] + records = [json.loads(raw) for raw in out.splitlines() if raw.strip()] + assert len(records) == 1 + assert records[0]["component"] == verbose_proxy_stdout_logger.name + assert records[0]["level"] == "WARNING" + + +def test_ordinary_proxy_records_still_propagate_to_root_handler(): + root_logger = logging.getLogger() + root_stream = StringIO() + root_handler = logging.StreamHandler(root_stream) + root_handler.setFormatter(logging.Formatter("ROOT %(levelname)s %(message)s")) + root_logger.addHandler(root_handler) + + try: + verbose_proxy_logger.error("ordinary proxy error") + finally: + root_logger.removeHandler(root_handler) + + assert "ROOT ERROR ordinary proxy error" in root_stream.getvalue() @pytest.mark.parametrize(