From 093bb642cfb764c5d033de2f9497eb8f66452d51 Mon Sep 17 00:00:00 2001 From: Yucheng Zhu Date: Wed, 26 Aug 2026 01:13:56 -0700 Subject: [PATCH] fix(logging): keep billing a background response when its retrieval is read A response created with background=true comes back queued and carries no usage, so its create bills nothing. The retrieval that first sees the finished job is the only place that job's tokens are ever visible, and pricing every read at zero therefore loses the spend outright rather than deduplicating it. On a proxy without the enterprise cost poller a background job ended up costing $0 end to end. is_unbilled_non_inference_call now takes the response it is deciding about and treats a background response the same way it already treats the poller's own read, which is the same exemption seen from the other side. The legacy OpenTelemetry emitter's time per output token metric picks up the read gate it was missing, so it stops dividing a read's latency by the replayed completion token count. --- litellm/integrations/opentelemetry.py | 21 ++++++--- .../internal_call_metadata.py | 31 +++++++++++-- litellm/litellm_core_utils/litellm_logging.py | 6 +-- .../spend_tracking/spend_tracking_utils.py | 2 +- .../integrations/test_opentelemetry.py | 40 +++++++++++++++-- .../test_litellm_logging.py | 44 ++++++++++++++++++- .../test_spend_tracking_utils.py | 22 +++++++++- 7 files changed, 146 insertions(+), 20 deletions(-) diff --git a/litellm/integrations/opentelemetry.py b/litellm/integrations/opentelemetry.py index 62aa2c24e74..cad9792c969 100644 --- a/litellm/integrations/opentelemetry.py +++ b/litellm/integrations/opentelemetry.py @@ -240,7 +240,9 @@ def _freeze_for_dedupe(value: object, _depth: int = 0) -> HashableScope: return repr(value) -def _is_unbilled_non_inference(call_type: object, litellm_params: Mapping[str, Any]) -> bool: +def _is_unbilled_non_inference( + call_type: str | None, litellm_params: Mapping[str, object] | None, response_obj: object +) -> bool: """Whether this call is a read or management route whose token counts describe an earlier request rather than this one. @@ -251,7 +253,10 @@ def _is_unbilled_non_inference(call_type: object, litellm_params: Mapping[str, A return False from litellm.litellm_core_utils.litellm_logging import StandardLoggingPayloadSetup - return is_unbilled_non_inference_call(call_type, StandardLoggingPayloadSetup.merge_litellm_metadata(litellm_params)) + metadata: Final = ( + StandardLoggingPayloadSetup.merge_litellm_metadata(litellm_params) if litellm_params is not None else None + ) + return is_unbilled_non_inference_call(call_type, metadata, response_obj) def _shutdown_tracer_provider(provider: "_SDKTracerProvider") -> None: @@ -1660,10 +1665,10 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): if self._operation_duration_histogram: self._operation_duration_histogram.record(duration_s, attributes=common_attrs) if ( - response_obj - and not _is_unbilled_non_inference(kwargs.get("call_type"), params) + self._token_usage_histogram + and response_obj + and not _is_unbilled_non_inference(kwargs.get("call_type"), params, response_obj) and (usage := response_obj.get("usage")) - and self._token_usage_histogram ): in_attrs: Final = {**common_attrs, TOKEN_TYPE_ATTRIBUTE: "input"} out_attrs: Final = {**common_attrs, TOKEN_TYPE_ATTRIBUTE: "output"} @@ -1740,6 +1745,9 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): if not self._time_per_output_token_histogram: return + if _is_unbilled_non_inference(kwargs.get("call_type"), kwargs.get("litellm_params"), response_obj): + return + # Get completion tokens from response_obj completion_tokens = None if response_obj and (usage := response_obj.get("usage")): @@ -2491,7 +2499,8 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): usage: Final = ( response_obj.get("usage") - if response_obj and not _is_unbilled_non_inference(kwargs.get("call_type"), litellm_params) + if response_obj + and not _is_unbilled_non_inference(kwargs.get("call_type"), litellm_params, response_obj) else None ) if usage: diff --git a/litellm/litellm_core_utils/internal_call_metadata.py b/litellm/litellm_core_utils/internal_call_metadata.py index 58ee5b4e18f..05c857f8c89 100644 --- a/litellm/litellm_core_utils/internal_call_metadata.py +++ b/litellm/litellm_core_utils/internal_call_metadata.py @@ -45,12 +45,35 @@ budget-checked like the request that spawned it. Everything else on the parent's be a lie on a sub-call that runs after it returned.""" -def is_unbilled_non_inference_call(call_type: str | None, metadata: Mapping[str, object] | None) -> bool: - """A read/management route priced at zero, except when the background response cost - poller made the read: that poll is the only place a background job's usage is ever - seen, so its retrieval carries the job's real spend.""" +def is_background_response(response: object) -> bool: + """Whether a retrieved object is a response created with ``background=true``. + + Such a create returns ``status="queued"`` and no usage at all, so nothing has billed the + job by the time anyone reads it back. Accepts the response as a mapping or a model, + because the callers hold it in both shapes. + """ + if isinstance(response, Mapping): + return response.get("background") is True + return getattr(response, "background", None) is True + + +def is_unbilled_non_inference_call( + call_type: str | None, + metadata: Mapping[str, object] | None, + response: object, +) -> bool: + """A read/management route priced at zero, because the usage it reports belongs to the + call that created the object it just read. + + Retrieving a background response is the exception, and the enterprise cost poller's read + is the same exception seen from the other side: that job's create billed nothing, so its + retrieval is the only place the spend is ever visible. Pricing those at zero would lose + the spend rather than deduplicate it. + """ if call_type not in NON_INFERENCE_CALL_TYPES: return False + if is_background_response(response): + return False if metadata is None: return True return metadata.get(INTERNAL_CALL_ORIGIN_METADATA_KEY) != BACKGROUND_RESPONSE_COST_POLL_CALL_ORIGIN diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index 26a12a4681a..47eb3854ac1 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -1581,7 +1581,7 @@ class Logging(LiteLLMLoggingBaseClass): return 0.0 if is_unbilled_non_inference_call( - self.call_type, StandardLoggingPayloadSetup.merge_litellm_metadata(self.litellm_params) + self.call_type, StandardLoggingPayloadSetup.merge_litellm_metadata(self.litellm_params), result ): return 0.0 @@ -4923,7 +4923,7 @@ class StandardLoggingPayloadSetup: return messages @staticmethod - def merge_litellm_metadata(litellm_params: dict) -> dict: + def merge_litellm_metadata(litellm_params: Mapping[str, object]) -> dict: """ Merge both litellm_metadata and metadata from litellm_params. @@ -5680,7 +5680,7 @@ def get_standard_logging_object_payload( cache_hit: Final = kwargs.get("cache_hit", False) # Extract usage as a plain dict, avoiding Pydantic round-trip raw_usage_dict: Final = StandardLoggingPayloadSetup.get_usage_as_dict( - response_obj=None if is_unbilled_non_inference_call(call_type, metadata) else response_obj, + response_obj=None if is_unbilled_non_inference_call(call_type, metadata, response_obj) else response_obj, combined_usage_object=cast(Usage | None, kwargs.get("combined_usage_object")), ) usage_dict: Final = ( diff --git a/litellm/proxy/spend_tracking/spend_tracking_utils.py b/litellm/proxy/spend_tracking/spend_tracking_utils.py index 3f2ca0ae96a..40e9dc0c3b4 100644 --- a/litellm/proxy/spend_tracking/spend_tracking_utils.py +++ b/litellm/proxy/spend_tracking/spend_tracking_utils.py @@ -276,7 +276,7 @@ def get_logging_payload(kwargs, response_obj, start_time, end_time) -> SpendLogs usage: dict = {} if call_type in ["ocr", "aocr"]: usage = _extract_usage_for_ocr_call(response_obj, response_obj_dict) - elif not is_unbilled_non_inference_call(call_type, metadata): + elif not is_unbilled_non_inference_call(call_type, metadata, response_obj_dict): # Use response_obj_dict instead of response_obj to avoid calling .get() on Pydantic models _usage: Final = response_obj_dict.get("usage", None) or {} if isinstance(_usage, litellm.Usage): diff --git a/tests/test_litellm/integrations/test_opentelemetry.py b/tests/test_litellm/integrations/test_opentelemetry.py index e0cdd7519ff..9ec8489f784 100644 --- a/tests/test_litellm/integrations/test_opentelemetry.py +++ b/tests/test_litellm/integrations/test_opentelemetry.py @@ -6356,6 +6356,7 @@ class TestOpenTelemetryNonInferenceUsage(unittest.TestCase): TOKEN_KEYS = frozenset({"gen_ai.usage.input_tokens", "gen_ai.usage.output_tokens", "gen_ai.usage.total_tokens"}) BACKGROUND_POLL = {"internal_call_origin": "background_response_cost_poll"} RESPONSE_OBJ = {"id": "resp_lit5602", "model": "gpt-4o", "usage": USAGE} + BACKGROUND_RESPONSE_OBJ = {**RESPONSE_OBJ, "background": True} def _kwargs(self, call_type, litellm_metadata=None): return { @@ -6369,25 +6370,36 @@ class TestOpenTelemetryNonInferenceUsage(unittest.TestCase): "standard_logging_object": {"id": "lit5602", "call_type": call_type, "metadata": {}}, } - def _token_attributes_on_span(self, call_type, litellm_metadata=None): + def _token_attributes_on_span(self, call_type, litellm_metadata=None, response_obj=None): otel = OpenTelemetry() mock_span = MagicMock() otel.set_attributes( span=mock_span, kwargs=self._kwargs(call_type, litellm_metadata), - response_obj=dict(self.RESPONSE_OBJ), + response_obj=response_obj or dict(self.RESPONSE_OBJ), ) return {call[0][0] for call in mock_span.set_attribute.call_args_list if call[0][0] in self.TOKEN_KEYS} - def _token_histogram_calls(self, call_type, litellm_metadata=None): + def _token_histogram_calls(self, call_type, litellm_metadata=None, response_obj=None): otel = OpenTelemetry() otel._operation_duration_histogram = MagicMock() otel._token_usage_histogram = MagicMock() otel._cost_histogram = None now = datetime.now() - otel._record_metrics(self._kwargs(call_type, litellm_metadata), dict(self.RESPONSE_OBJ), now, now) + otel._record_metrics( + self._kwargs(call_type, litellm_metadata), response_obj or dict(self.RESPONSE_OBJ), now, now + ) return otel._token_usage_histogram.record.call_count + def _time_per_output_token_calls(self, call_type, litellm_metadata=None, response_obj=None): + otel = OpenTelemetry() + otel._time_per_output_token_histogram = MagicMock() + now = datetime.now() + otel._record_time_per_output_token_metric( + self._kwargs(call_type, litellm_metadata), response_obj or dict(self.RESPONSE_OBJ), now, 1.0, {} + ) + return otel._time_per_output_token_histogram.record.call_count + def test_inference_call_still_reports_its_tokens_on_the_span(self): self.assertEqual(self._token_attributes_on_span("acompletion"), set(self.TOKEN_KEYS)) @@ -6405,3 +6417,23 @@ class TestOpenTelemetryNonInferenceUsage(unittest.TestCase): def test_background_cost_poll_read_still_records_the_token_usage_histogram(self): self.assertEqual(self._token_histogram_calls("aget_responses", self.BACKGROUND_POLL), 2) + + def test_background_response_read_still_reports_its_tokens_on_the_span(self): + self.assertEqual( + self._token_attributes_on_span("aget_responses", response_obj=self.BACKGROUND_RESPONSE_OBJ), + set(self.TOKEN_KEYS), + ) + + def test_background_response_read_still_records_the_token_usage_histogram(self): + self.assertEqual(self._token_histogram_calls("aget_responses", response_obj=self.BACKGROUND_RESPONSE_OBJ), 2) + + def test_inference_call_still_records_time_per_output_token(self): + self.assertEqual(self._time_per_output_token_calls("acompletion"), 1) + + def test_response_read_does_not_divide_its_latency_by_the_retrieved_token_count(self): + self.assertEqual(self._time_per_output_token_calls("aget_responses"), 0) + + def test_background_response_read_still_records_time_per_output_token(self): + self.assertEqual( + self._time_per_output_token_calls("aget_responses", response_obj=self.BACKGROUND_RESPONSE_OBJ), 1 + ) diff --git a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py index 542617cc159..e106f4a1d98 100644 --- a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py +++ b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py @@ -4857,7 +4857,7 @@ class TestNonInferenceCallTypesAreNotBilled: ) return obj - def _retrieved_response(self): + def _retrieved_response(self, background: bool | None = None): from litellm.types.llms.openai import ResponsesAPIResponse return ResponsesAPIResponse( @@ -4866,6 +4866,7 @@ class TestNonInferenceCallTypesAreNotBilled: model="gpt-4o", output=[], usage=self.RETRIEVED_RESPONSE_USAGE, + background=background, ) def test_creating_a_response_is_still_priced(self): @@ -4953,6 +4954,47 @@ class TestNonInferenceCallTypesAreNotBilled: assert payload is not None assert payload["total_tokens"] == 6000 + def test_reading_a_background_response_is_still_priced(self): + """A background create answers queued with no usage at all, so whoever reads the finished + job is the first and only caller to see its tokens. Zeroing that read bills the job nothing.""" + cost = self._logging_obj("aget_responses")._response_cost_calculator( + result=self._retrieved_response(background=True) + ) + assert cost is not None and cost > 0 + + def test_reading_a_background_response_reports_usage_in_standard_logging_payload(self): + from datetime import datetime + + from litellm.litellm_core_utils.litellm_logging import ( + get_standard_logging_object_payload, + ) + + now = datetime.now() + payload = get_standard_logging_object_payload( + kwargs={ + "litellm_call_id": "lit5602-background-payload", + "model": "gpt-4o", + "call_type": "aget_responses", + "litellm_params": {}, + }, + init_response_obj=self._retrieved_response(background=True), + start_time=now, + end_time=now, + logging_obj=self._logging_obj("aget_responses"), + status="success", + ) + + assert payload is not None + assert payload["total_tokens"] == 6000 + + def test_reading_a_foreground_response_is_still_free(self): + """Guards the test above against a blanket exemption: an explicit background=false read was + already billed by its create and must stay at zero.""" + cost = self._logging_obj("aget_responses")._response_cost_calculator( + result=self._retrieved_response(background=False) + ) + assert cost == 0.0 + def _read_call_messages(self): logging_obj, _ = litellm.utils.function_setup( original_function="aget_responses", diff --git a/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py b/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py index fc9632e5723..f00160edae8 100644 --- a/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py +++ b/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py @@ -3275,7 +3275,9 @@ def test_user_traffic_carries_no_internal_call_origin(): assert metadata["internal_call_origin"] is None -def _spend_log_for_call_type(call_type: str, internal_call_origin: str | None = None) -> dict: +def _spend_log_for_call_type( + call_type: str, internal_call_origin: str | None = None, background: bool | None = None +) -> dict: from litellm.types.llms.openai import ResponsesAPIResponse return cast( @@ -3298,6 +3300,7 @@ def _spend_log_for_call_type(call_type: str, internal_call_origin: str | None = model="gpt-4o", output=[], usage={"input_tokens": 4000, "output_tokens": 2000, "total_tokens": 6000}, + background=background, ), start_time=datetime.datetime.now(timezone.utc), end_time=datetime.datetime.now(timezone.utc), @@ -3324,6 +3327,23 @@ def test_spend_log_for_background_response_cost_poll_counts_tokens(): assert payload["total_tokens"] == 6000 +def test_spend_log_for_background_response_retrieval_counts_tokens(): + """A background create answers queued carrying no usage, so its retrieval is the first and only + place the job's tokens are ever visible. Zeroing that read bills the whole job nothing on any + proxy that is not running the enterprise cost poller.""" + payload = _spend_log_for_call_type("aget_responses", background=True) + + assert payload["total_tokens"] == 6000 + + +def test_spend_log_for_foreground_response_retrieval_still_counts_nothing(): + """Guards the test above against a blanket exemption: an explicit background=false read was + already billed by its create and must stay at zero.""" + payload = _spend_log_for_call_type("aget_responses", background=False) + + assert payload["total_tokens"] == 0 + + def test_spend_log_for_response_creation_still_counts_tokens(): """Guards the test above: the same response object must still be counted on the create path.""" payload = _spend_log_for_call_type("aresponses")