From 116dd0504c9c77fd5c7c0930a2b03d6f37b7603b Mon Sep 17 00:00:00 2001 From: mateo-berri <277851410+mateo-berri@users.noreply.github.com> Date: Thu, 8 Oct 2026 07:26:14 -0700 Subject: [PATCH] fix(proxy): keep allowlisted metadata in proxy-only failure logs Backport of #50 to rc/1.105.0. Cherry-picked from 9722ca937e (main). --- litellm/litellm_core_utils/litellm_logging.py | 20 ++- litellm/proxy/utils.py | 96 ++++++++++++-- .../test_litellm_logging.py | 15 +++ ..._utils_model_creation_and_error_logging.py | 108 +++++++++++++++- .../test_post_call_failure_hook.py | 122 +++++++++++++++++- 5 files changed, 329 insertions(+), 32 deletions(-) diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index 2b2f6e9b41b..30f1604d152 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -6478,19 +6478,17 @@ class StandardLoggingPayloadSetup: litellm_metadata: Final = cast( # cast-ok: request metadata is caller-provided Mapping[str, object], litellm_params.get("litellm_metadata") or {} ) - if metadata.get("tags", []): - request_tags = cast(list[str], metadata.get("tags", [])).copy() # cast-ok: tags are caller-provided - elif litellm_metadata.get("tags", []): - request_tags = cast(list[str], litellm_metadata.get("tags", [])).copy() # cast-ok: tags are caller-provided - else: - request_tags = [] + request_tags: Final = next( + ( + cast(list[str], tags) # cast-ok: tags are caller-provided + for tags in (metadata.get("tags"), litellm_metadata.get("tags")) + if isinstance(tags, list) and tags + ), + [], + ) user_agent_tags: Final = StandardLoggingPayloadSetup._get_user_agent_tags(proxy_server_request) additional_header_tags: Final = StandardLoggingPayloadSetup._get_extra_header_tags(proxy_server_request) - if user_agent_tags is not None: - request_tags.extend(user_agent_tags) - if additional_header_tags is not None: - request_tags.extend(additional_header_tags) - return request_tags + return [*request_tags, *(user_agent_tags or ()), *(additional_header_tags or ())] _get_request_tags = get_request_tags diff --git a/litellm/proxy/utils.py b/litellm/proxy/utils.py index 58b103ec739..bd9d714f74a 100644 --- a/litellm/proxy/utils.py +++ b/litellm/proxy/utils.py @@ -1237,7 +1237,8 @@ def _stamp_deployment_attribution( callbacks key off it and must not count a proxy-side reject against the deployment. A failure after the provider handoff keeps the metadata the router stamped; a request that never reached a provider is flagged ``PROXY_REJECTED_BEFORE_ROUTING_KEY`` (deployment metrics key off it) whatever - its metadata says, since ``metadata.model_info`` can be caller supplied.""" + its metadata says, since ``metadata.model_info`` can be caller supplied. Its ``deployment`` and + ``model_group`` always come from the router config, never from the caller's metadata.""" attribution: Final = _deployment_attribution_for_model_group(model_group, team_id) if "custom_llm_provider" in attribution: litellm_params["custom_llm_provider"] = attribution["custom_llm_provider"] @@ -1252,9 +1253,13 @@ def _stamp_deployment_attribution( if not isinstance(metadata, dict): return attribution metadata.setdefault("model_info", attribution["model_info"]) - metadata.setdefault("deployment", attribution["deployment"]) - if isinstance(model_group, str): - metadata.setdefault("model_group", model_group) + routing: Final = MappingProxyType( + {"deployment": attribution["deployment"], **({"model_group": model_group} if model_group else {})} + ) + metadata.update(routing) + litellm_metadata: Final = litellm_params.get("litellm_metadata") + if isinstance(litellm_metadata, dict): + litellm_metadata.update(routing) return attribution @@ -1333,8 +1338,50 @@ _PROXY_ONLY_ERROR_LOGGED_FIELDS: Final = frozenset( ) -def _proxy_only_error_log_fields(request_data: Mapping[str, _T]) -> Mapping[str, _T]: - return MappingProxyType({k: v for k, v in request_data.items() if k in _PROXY_ONLY_ERROR_LOGGED_FIELDS}) +def _as_str_mapping(value: object) -> Mapping[str, object]: + if not isinstance(value, Mapping): + return MappingProxyType({}) + return cast( # cast-ok: the runtime Mapping check validates the container shape + Mapping[str, object], value + ) + + +def _proxy_only_error_logged_metadata_keys(*, authenticated: bool, past_pre_call: bool) -> frozenset[str]: + return frozenset( + key + for key, logged in (("tags", authenticated), ("standard_logging_guardrail_information", past_pre_call)) + if logged + ) + + +def _is_logged_metadata_value(key: str, value: object) -> bool: + return key != "tags" or (isinstance(value, list) and all(isinstance(item, str) for item in value)) + + +def _proxy_only_error_log_metadata(value: object, logged_keys: frozenset[str]) -> dict[str, object] | None: + if not isinstance(value, Mapping): + return None + metadata: Final = _as_str_mapping(value) + return { + key: value for key, value in metadata.items() if key in logged_keys and _is_logged_metadata_value(key, value) + } + + +def _proxy_only_error_log_fields( + request_data: Mapping[str, object], logged_metadata_keys: frozenset[str] +) -> Mapping[str, object]: + metadata_fields: Final = { + key: filtered_metadata + for key in ("metadata", "litellm_metadata") + if (filtered_metadata := _proxy_only_error_log_metadata(request_data.get(key), logged_metadata_keys)) + is not None + } + return MappingProxyType( + { + **{key: value for key, value in request_data.items() if key in _PROXY_ONLY_ERROR_LOGGED_FIELDS}, + **metadata_fields, + } + ) _EXCEPTION_CHAIN_MAX_DEPTH: Final = 16 @@ -3614,6 +3661,7 @@ class ProxyLogging: user_api_key_dict=user_api_key_dict, route=route, original_exception=original_exception, + error_type=error_type, ) request_data.update( @@ -3702,6 +3750,7 @@ class ProxyLogging: user_api_key_dict: UserAPIKeyAuth, route: str | None = None, original_exception: Exception | None = None, + error_type: ProxyErrorTypes | None = None, ): """ Handle logging for proxy only errors by calling `litellm_logging_obj.async_failure_handler` @@ -3709,19 +3758,22 @@ class ProxyLogging: Is triggered when self._is_proxy_only_error() returns True """ litellm_logging_obj: Logging | None = request_data.get("litellm_logging_obj", None) + logged_metadata_keys: Final = _proxy_only_error_logged_metadata_keys( + authenticated=error_type != ProxyErrorTypes.auth_error, past_pre_call=litellm_logging_obj is not None + ) + user_api_key_logged_metadata: Final = LiteLLMProxyRequestSetup.get_sanitized_user_information_from_key( + user_api_key_dict=user_api_key_dict + ) if litellm_logging_obj is None: from litellm._uuid import uuid request_data.setdefault("litellm_call_id", str(uuid.uuid4())) - user_api_key_logged_metadata: Final = LiteLLMProxyRequestSetup.get_sanitized_user_information_from_key( - user_api_key_dict=user_api_key_dict - ) litellm_logging_obj, data = litellm.utils.function_setup( original_function=route or "IGNORE_THIS", rules_obj=litellm.utils.Rules(), start_time=datetime.now(), - **_proxy_only_error_log_fields(request_data), + **_proxy_only_error_log_fields(request_data, logged_metadata_keys), ) request_data["litellm_logging_obj"] = litellm_logging_obj # rebind-ok: lifted then popped by the caller if "metadata" not in request_data: @@ -3734,14 +3786,32 @@ class ProxyLogging: _litellm_params: Final = {} litellm_param_keys: Final = LoggedLiteLLMParams.__annotations__.keys() - for k, v in _proxy_only_error_log_fields(request_data).items(): + for k, v in _proxy_only_error_log_fields(request_data, logged_metadata_keys).items(): if k in litellm_param_keys: _litellm_params[k] = v elif k not in ("model", "user", "litellm_logging_obj"): _optional_params[k] = v + existing: Final = _as_str_mapping(litellm_logging_obj.litellm_params) + litellm_params: Final = { + **_litellm_params, + "metadata": { + **_as_str_mapping(existing.get("metadata")), + **_as_str_mapping(_litellm_params.get("metadata")), + **user_api_key_logged_metadata, + }, + **{ + key: { + **_as_str_mapping(existing.get(key)), + **_as_str_mapping(value), + } + for key, value in _litellm_params.items() + if key == "litellm_metadata" + }, + } + attribution: Final = _stamp_deployment_attribution( - _litellm_params, + litellm_params, request_data.get("model"), user_api_key_dict.team_id, dispatched=_reached_deployment(litellm_logging_obj), @@ -3751,7 +3821,7 @@ class ProxyLogging: model=request_data.get("model", ""), user=request_data.get("user", ""), optional_params=_optional_params, - litellm_params=_litellm_params, + litellm_params=litellm_params, **( {"custom_llm_provider": attribution["custom_llm_provider"]} if "custom_llm_provider" in attribution diff --git a/tests/unit/litellm_core_utils/test_litellm_logging.py b/tests/unit/litellm_core_utils/test_litellm_logging.py index 346f54622f3..6ddea8c95e6 100644 --- a/tests/unit/litellm_core_utils/test_litellm_logging.py +++ b/tests/unit/litellm_core_utils/test_litellm_logging.py @@ -3140,6 +3140,21 @@ def test_get_request_tags_from_metadata_and_litellm_metadata(): assert "User-Agent: litellm/1.0.0" in tags +@pytest.mark.parametrize("unusable_metadata_tags", [123, "tag", {"tag": True}, []]) +def test_get_request_tags_falls_back_to_litellm_metadata_when_metadata_tags_are_unusable(unusable_metadata_tags): + from litellm.litellm_core_utils.litellm_logging import StandardLoggingPayloadSetup + + tags = StandardLoggingPayloadSetup._get_request_tags( + litellm_params={ + "metadata": {"tags": unusable_metadata_tags}, + "litellm_metadata": {"tags": ["litellm-metadata-tag"]}, + }, + proxy_server_request={}, + ) + + assert tags == ["litellm-metadata-tag"] + + def test_get_request_tags_does_not_mutate_original_tags(): """ Test that _get_request_tags does not mutate the original tags list in metadata. diff --git a/tests/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py b/tests/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py index 4121dca8ae1..33b6718893d 100644 --- a/tests/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py +++ b/tests/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py @@ -117,11 +117,58 @@ async def test_proxy_only_error_log_marks_no_upstream_llm_call(): @pytest.mark.asyncio @pytest.mark.parametrize("metadata_field", ["metadata", "litellm_metadata"]) -async def test_proxy_only_error_log_drops_caller_logging_fields_and_metadata(metadata_field: str): +async def test_proxy_only_error_log_drops_caller_guardrail_information_without_logging_object( + metadata_field: str, + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setattr(litellm, "callbacks", []) + monkeypatch.setattr(litellm, "input_callback", []) + monkeypatch.setattr(litellm, "failure_callback", []) + monkeypatch.setattr(litellm, "_async_failure_callback", []) + guardrail_info: Final = [ + { + "guardrail_name": "caller-guardrail", + "guardrail_status": "guardrail_intervened", + "guardrail_cost": 123.45, + } + ] request_data: Final[dict[str, object]] = { "model": "gpt-4o", "messages": [{"role": "user", "content": "hi"}], - metadata_field: {"langsmith_base_url": "https://caller.invalid", "langsmith_api_key": "caller-key"}, + metadata_field: {"tags": ["t"], "standard_logging_guardrail_information": guardrail_info}, + } + + await ProxyLogging(user_api_key_cache=DualCache())._handle_logging_proxy_only_error( + request_data=request_data, + user_api_key_dict=UserAPIKeyAuth(api_key="sk-rejected", team_id="team-a", request_route="/v1/chat/completions"), + route="/v1/chat/completions", + original_exception=HTTPException(status_code=400, detail="blocked"), + ) + + details: Final = request_data["litellm_logging_obj"].model_call_details + assert details["standard_logging_object"] is not None + assert details["litellm_params"][metadata_field]["tags"] == ["t"] + assert "standard_logging_guardrail_information" not in details["litellm_params"][metadata_field] + assert "guardrail_cost" not in str(details["standard_logging_object"]) + assert "litellm_metadata" not in details["optional_params"] + + +@pytest.mark.asyncio +@pytest.mark.parametrize("metadata_field", ["metadata", "litellm_metadata"]) +async def test_proxy_only_error_log_keeps_tags_and_drops_caller_logging_fields( + metadata_field: str, +) -> None: + request_data: Final[dict[str, object]] = { + "model": "gpt-4o", + "messages": [{"role": "user", "content": "hi"}], + metadata_field: { + "langsmith_base_url": "https://caller.invalid", + "langsmith_api_key": "caller-key", + "tags": ["t"], + "user_api_key_team_id": "caller-team", + "user_api_key_hash": "caller-hash", + "user_api_key_auth_metadata": {"caller": "metadata"}, + }, "langsmith_base_url": "https://caller.invalid", "standard_callback_dynamic_params": {"gcs_path_service_account": "/caller/sa.json"}, } @@ -137,6 +184,63 @@ async def test_proxy_only_error_log_drops_caller_logging_fields_and_metadata(met assert "caller" not in str(details["standard_callback_dynamic_params"]) assert "langsmith_base_url" not in details assert "caller" not in str(details["litellm_params"]) + assert details["litellm_params"][metadata_field]["tags"] == ["t"] + assert details["litellm_params"]["metadata"]["user_api_key_team_id"] == "team-a" + + +@pytest.mark.asyncio +@pytest.mark.parametrize("metadata_field", ["metadata", "litellm_metadata"]) +async def test_proxy_only_error_log_drops_malformed_metadata_tags(metadata_field: str) -> None: + guardrail_info: Final = [{"guardrail_name": "g", "guardrail_status": "guardrail_intervened"}] + request_data: Final[dict[str, object]] = { + "model": "gpt-4o", + "messages": [{"role": "user", "content": "hi"}], + metadata_field: {"tags": 123, "standard_logging_guardrail_information": guardrail_info}, + } + + await ProxyLogging(user_api_key_cache=DualCache())._handle_logging_proxy_only_error( + request_data=request_data, + user_api_key_dict=UserAPIKeyAuth(api_key="sk-rejected", team_id="team-a", request_route="/v1/chat/completions"), + route="/v1/chat/completions", + original_exception=Exception("bad key"), + ) + + details: Final = request_data["litellm_logging_obj"].model_call_details + assert details["standard_logging_object"] is not None + assert "tags" not in details["litellm_params"][metadata_field] + assert "standard_logging_guardrail_information" not in details["litellm_params"][metadata_field] + + +@pytest.mark.asyncio +@pytest.mark.parametrize("metadata_field", ["metadata", "litellm_metadata"]) +async def test_proxy_only_error_log_builds_payload_when_logging_object_has_malformed_tags( + metadata_field: str, +) -> None: + request_data: Final[dict[str, object]] = { + "model": "gpt-4o", + "messages": [{"role": "user", "content": "hi"}], + "litellm_call_id": "malformed-tags-call", + metadata_field: {"tags": 123}, + } + logging_obj, _ = litellm.utils.function_setup( + original_function="acompletion", + rules_obj=litellm.utils.Rules(), + start_time=real_datetime.datetime.now(), + **request_data, + ) + + await ProxyLogging(user_api_key_cache=DualCache())._handle_logging_proxy_only_error( + request_data={**request_data, "litellm_logging_obj": logging_obj}, + user_api_key_dict=UserAPIKeyAuth(api_key="sk-blocked", team_id="team-a", request_route="/v1/chat/completions"), + route="/v1/chat/completions", + original_exception=HTTPException(status_code=400, detail="Content blocked"), + ) + + standard_logging_object: Final = logging_obj.model_call_details["standard_logging_object"] + assert standard_logging_object is not None + assert standard_logging_object["model"] == request_data["model"] + assert standard_logging_object["metadata"]["user_api_key_team_id"] == "team-a" + assert 123 not in standard_logging_object["request_tags"] @pytest.mark.asyncio diff --git a/tests/unit/proxy/utils/proxy_logging/test_post_call_failure_hook.py b/tests/unit/proxy/utils/proxy_logging/test_post_call_failure_hook.py index a9b399c550a..3a11877c99f 100644 --- a/tests/unit/proxy/utils/proxy_logging/test_post_call_failure_hook.py +++ b/tests/unit/proxy/utils/proxy_logging/test_post_call_failure_hook.py @@ -357,6 +357,103 @@ async def test_post_call_failure_hook_flags_pre_routing_reject_despite_caller_mo assert kwargs["litellm_params"]["custom_llm_provider"] == "openai" +@pytest.mark.asyncio +@pytest.mark.parametrize("metadata_field", ["metadata", "litellm_metadata"]) +async def test_pre_routing_reject_logs_the_configured_deployment_over_caller_metadata( + proxy_logging, make_user_api_key_auth, monkeypatch, metadata_field: str +): + from litellm.proxy import proxy_server + from litellm.proxy.spend_tracking.spend_tracking_utils import get_logging_payload + + recorded: list[dict] = [] + + class _RecordingLogger(CustomLogger): + async def async_log_failure_event(self, kwargs, response_obj, start_time, end_time): + recorded.append(kwargs) + + monkeypatch.setattr( + proxy_server, + "llm_router", + litellm.Router( + model_list=[ + { + "model_name": "internal-model", + "litellm_params": {"model": "openai/gpt-4.1", "api_key": "sk-test"}, + } + ] + ), + ) + monkeypatch.setattr(litellm, "callbacks", [_RecordingLogger()]) + proxy_logging.alert_types = [] + request_data: Final[dict[str, object]] = { + "model": "internal-model", + "messages": [{"role": "user", "content": "hi"}], + "litellm_call_id": "caller-routing-metadata", + metadata_field: {"deployment": "openai/caller-chosen", "model_group": "caller-group"}, + } + logging_obj, _ = litellm.utils.function_setup( + original_function="acompletion", rules_obj=litellm.utils.Rules(), start_time=datetime.now(), **request_data + ) + + await proxy_logging.post_call_failure_hook( + request_data={**request_data, "litellm_logging_obj": logging_obj}, + original_exception=HTTPException(status_code=400, detail="Content blocked"), + user_api_key_dict=make_user_api_key_auth(request_route="/chat/completions"), + route="/chat/completions", + ) + + assert len(recorded) == 1 + now: Final = datetime.now() + payload: Final = get_logging_payload( + kwargs={**recorded[0], "completion_start_time": now}, response_obj=None, start_time=now, end_time=now + ) + standard_logging_object: Final = recorded[0]["standard_logging_object"] + assert { + "logged_model": standard_logging_object["model"], + "logged_model_group": standard_logging_object["model_group"], + "spend_model": payload["model"], + "spend_model_group": payload["model_group"], + } == { + "logged_model": "openai/gpt-4.1", + "logged_model_group": "internal-model", + "spend_model": "openai/gpt-4.1", + "spend_model_group": "internal-model", + } + + +@pytest.mark.asyncio +@pytest.mark.parametrize(("error_type", "logged_tags"), [(ProxyErrorTypes.auth_error, []), (None, ["checkout"])]) +async def test_proxy_only_failure_log_keeps_caller_tags_only_after_auth( + proxy_logging, monkeypatch, error_type: ProxyErrorTypes | None, logged_tags: list[str] +): + from litellm.proxy import proxy_server + + recorded: list[dict] = [] + + class _RecordingLogger(CustomLogger): + async def async_log_failure_event(self, kwargs, response_obj, start_time, end_time): + recorded.append(kwargs) + + monkeypatch.setattr(proxy_server, "llm_router", None) + monkeypatch.setattr(litellm, "callbacks", [_RecordingLogger()]) + proxy_logging.alert_types = [] + + await proxy_logging.post_call_failure_hook( + request_data={ + "model": "internal-model", + "messages": [{"role": "user", "content": "hi"}], + "metadata": {"tags": ["checkout"]}, + }, + original_exception=HTTPException(status_code=401, detail="Invalid proxy server token passed"), + user_api_key_dict=UserAPIKeyAuth(request_route="/chat/completions"), + error_type=error_type, + route="/chat/completions", + ) + + assert len(recorded) == 1 + assert recorded[0]["standard_logging_object"]["request_tags"] == logged_tags + + @pytest.mark.asyncio async def test_post_call_failure_hook_attribution_does_not_count_against_the_deployment( proxy_logging, make_user_api_key_auth, monkeypatch @@ -529,9 +626,8 @@ async def test_post_call_failure_hook_omits_provider_when_a_deployment_does_not_ async def test_handle_logging_proxy_only_path_attributes_with_read_only_metadata( proxy_logging, make_user_api_key_auth, monkeypatch ): - """With a logging object already on the request, a read-only metadata mapping - must not crash the stamp, the failure handler still receives the provider - attribution, and the request's metadata is not copied into the update.""" + """With a logging object already on the request, allowlisted metadata is kept, + a read-only mapping must not crash the stamp, and the failure handler receives provider attribution.""" from litellm.proxy import proxy_server monkeypatch.setattr( @@ -550,16 +646,26 @@ async def test_handle_logging_proxy_only_path_attributes_with_read_only_metadata logging_obj = MagicMock() logging_obj.call_type = "acompletion" logging_obj.model_call_details = {} + logging_obj.litellm_params = {"metadata": {"preexisting": "logged"}} logging_obj.async_failure_handler = AsyncMock() + guardrail_info: Final = [ + { + "guardrail_name": "local-block", + "guardrail_status": "guardrail_intervened", + "guardrail_cost": 0.25, + } + ] await proxy_logging._handle_logging_proxy_only_error( request_data={ "litellm_logging_obj": logging_obj, "model": "internal-model", "messages": [{"role": "user", "content": "hi"}], - "metadata": MappingProxyType({"user_api_key_alias": "frozen"}), + "metadata": MappingProxyType( + {"tags": ["checkout"], "standard_logging_guardrail_information": guardrail_info} + ), }, - user_api_key_dict=make_user_api_key_auth(request_route="/chat/completions"), + user_api_key_dict=make_user_api_key_auth(request_route="/chat/completions", key_alias="frozen"), route="/chat/completions", original_exception=HTTPException(status_code=403, detail="blocked"), ) @@ -568,7 +674,11 @@ async def test_handle_logging_proxy_only_path_attributes_with_read_only_metadata update_kwargs = logging_obj.update_environment_variables.call_args.kwargs assert update_kwargs["custom_llm_provider"] == "openai" assert update_kwargs["litellm_params"]["custom_llm_provider"] == "openai" - assert "user_api_key_alias" not in update_kwargs["litellm_params"]["metadata"] + assert { + key: update_kwargs["litellm_params"]["metadata"][key] for key in ("preexisting", "user_api_key_alias") + } == {"preexisting": "logged", "user_api_key_alias": "frozen"} + assert update_kwargs["litellm_params"]["metadata"]["tags"] == ["checkout"] + assert update_kwargs["litellm_params"]["metadata"]["standard_logging_guardrail_information"] == guardrail_info @pytest.mark.asyncio