From 9e8a847c5b797457a16e187e538b4a0592946766 Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Sat, 19 Sep 2026 03:21:28 -0700 Subject: [PATCH] fix(proxy): keep request metadata out of the cost tracking failure alert The cost tracking callback f-stringed chosen_metadata, litellm_metadata, and old_metadata into the failed_tracking_spend alert on every failure, at every log level, so one 250-byte request produced a 23 KB alert carrying the client's metadata, headers, and key-auth reprs four times over. The alert now carries the exception, the traceback, the model, and the call type; the metadata keys are logged once at debug level through lazy formatting, so nothing is built at warning level --- .../proxy/hooks/proxy_track_cost_callback.py | 33 +++++--- .../hooks/test_proxy_track_cost_callback.py | 78 +++++++++++++++++++ 2 files changed, 102 insertions(+), 9 deletions(-) diff --git a/litellm/proxy/hooks/proxy_track_cost_callback.py b/litellm/proxy/hooks/proxy_track_cost_callback.py index 903255c7b6c..b38fb856215 100644 --- a/litellm/proxy/hooks/proxy_track_cost_callback.py +++ b/litellm/proxy/hooks/proxy_track_cost_callback.py @@ -1,6 +1,6 @@ import asyncio import traceback -from collections.abc import Callable, Sequence +from collections.abc import Callable, Mapping, Sequence from datetime import datetime from typing import TYPE_CHECKING, Any, Final, cast @@ -446,17 +446,26 @@ class _ProxyDBLogger(CustomLogger): f"Cost tracking failed for model={model}.\nDebug info - {cost_tracking_failure_debug_info}\nAdd custom pricing - https://docs.litellm.ai/docs/proxy/custom_pricing" ) except Exception as e: - error_msg = f"Error in tracking cost callback - {e}\n Traceback:{traceback.format_exc()}" - model = kwargs.get("model", "") - metadata = get_litellm_metadata_from_kwargs(kwargs=kwargs) - litellm_metadata: Final = kwargs.get("litellm_params", {}).get("litellm_metadata", {}) - old_metadata: Final = kwargs.get("litellm_params", {}).get("metadata", {}) - call_type = kwargs.get("call_type", "") - error_msg += f"\n Args to _PROXY_track_cost_callback\n model: {model}\n chosen_metadata: {metadata}\n litellm_metadata: {litellm_metadata}\n old_metadata: {old_metadata}\n call_type: {call_type}\n" + failing_model: Final = kwargs.get("model", "") + failing_call_type: Final = kwargs.get("call_type", "") + error_msg: Final = ( + f"Error in tracking cost callback - {e}\n Traceback:{traceback.format_exc()}\n" + f" Args to _PROXY_track_cost_callback\n model: {failing_model}\n call_type: {failing_call_type}\n" + ) + failing_litellm_params: Final = kwargs.get("litellm_params") or {} + verbose_proxy_logger.debug( + "Cost tracking callback failed for model=%s call_type=%s;" + " chosen_metadata keys=%s litellm_metadata keys=%s old_metadata keys=%s", + failing_model, + failing_call_type, + _metadata_keys(get_litellm_metadata_from_kwargs(kwargs=kwargs)), + _metadata_keys(failing_litellm_params.get("litellm_metadata")), + _metadata_keys(failing_litellm_params.get("metadata")), + ) asyncio.create_task( proxy_logging_obj.failed_tracking_alert( error_message=error_msg, - failing_model=model, + failing_model=failing_model, ) ) @@ -614,6 +623,12 @@ def _should_track_cost_callback( return call_type in _UNATTRIBUTED_TRACKABLE_CALL_TYPES +def _metadata_keys(metadata: object) -> tuple[str, ...]: + if not isinstance(metadata, Mapping): + return () + return tuple(sorted(str(key) for key in metadata)) + + def _get_budget_reservation_from_metadata(metadata: dict) -> dict | None: metadata_budget_reservation: Final = metadata.get("user_api_key_budget_reservation") if isinstance(metadata_budget_reservation, dict): diff --git a/tests/test_litellm/proxy/hooks/test_proxy_track_cost_callback.py b/tests/test_litellm/proxy/hooks/test_proxy_track_cost_callback.py index 202495517ad..0e9c336a9eb 100644 --- a/tests/test_litellm/proxy/hooks/test_proxy_track_cost_callback.py +++ b/tests/test_litellm/proxy/hooks/test_proxy_track_cost_callback.py @@ -1,11 +1,13 @@ import asyncio import json +import logging from datetime import datetime from typing import Final from unittest.mock import AsyncMock, MagicMock, patch import pytest +from litellm._logging import verbose_proxy_logger from litellm.litellm_core_utils.internal_call_metadata import MODEL_ACCESS_GROUP_METADATA_KEY from litellm.proxy._types import SpendLogsPayload, UserAPIKeyAuth from litellm.proxy.collector import SpendEventConsumer @@ -2540,3 +2542,79 @@ async def test_async_post_call_failure_hook_persists_no_raw_model_on_an_unknown_ == "/chat/completions: Invalid model name passed in. Call `/v1/models` to view available models for your key." ) assert error_information["error_class"] == "ProxyModelNotFoundError" + + +class _NeverStringifiedMetadataValue: + def __repr__(self) -> str: + raise AssertionError("a request metadata value was stringified by the cost tracking failure path") + + __str__ = __repr__ + + +def _spend_write_kwargs_with_metadata_value(metadata_value: object) -> dict: + return { + "call_type": "acompletion", + "model": "gpt-5.4-mini", + "litellm_call_id": "test-call-id", + "stream": False, + "response_cost": 4.725e-05, + "litellm_params": { + "metadata": { + "user_api_key": "hashed-key", + "user_api_key_user_id": "user-1", + "user_context": metadata_value, + "headers": {"user-agent": metadata_value}, + }, + }, + } + + +@pytest.mark.asyncio +@pytest.mark.parametrize("log_level", [logging.WARNING, logging.DEBUG]) +async def test_track_cost_callback_failure_alert_never_carries_request_metadata_values(log_level): + logger: Final = _ProxyDBLogger() + records: list[logging.LogRecord] = [] + handler: Final = logging.Handler() + handler.emit = records.append + previous_level: Final = verbose_proxy_logger.level + verbose_proxy_logger.setLevel(log_level) + verbose_proxy_logger.addHandler(handler) + try: + with patch( # test-quality-ok: callback imports proxy_logging_obj off proxy_server in its body, no seam + "litellm.proxy.proxy_server.proxy_logging_obj" + ) as mock_proxy_logging: + mock_proxy_logging.failed_tracking_alert = AsyncMock() + mock_proxy_logging.db_spend_update_writer = MagicMock() + mock_proxy_logging.db_spend_update_writer.update_database = AsyncMock( + side_effect=Exception("READONLY You can't write against a read only replica.") + ) + + await logger._PROXY_track_cost_callback( + kwargs=_spend_write_kwargs_with_metadata_value(_NeverStringifiedMetadataValue()), + completion_response=ModelResponse(), + start_time=datetime.now(), + end_time=datetime.now(), + ) + await asyncio.sleep(0) + finally: + verbose_proxy_logger.removeHandler(handler) + verbose_proxy_logger.setLevel(previous_level) + + mock_proxy_logging.failed_tracking_alert.assert_awaited_once() + alert: Final = mock_proxy_logging.failed_tracking_alert.await_args.kwargs + assert alert["failing_model"] == "gpt-5.4-mini" + assert "READONLY You can't write against a read only replica." in alert["error_message"] + assert "model: gpt-5.4-mini" in alert["error_message"] + assert "call_type: acompletion" in alert["error_message"] + + failure_debug_lines: Final = [ + record.getMessage() + for record in records + if record.levelno == logging.DEBUG and "Cost tracking callback failed" in record.getMessage() + ] + if log_level == logging.DEBUG: + assert len(failure_debug_lines) == 1 + assert "user_context" in failure_debug_lines[0] + assert "headers" in failure_debug_lines[0] + else: + assert failure_debug_lines == []