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.
This commit is contained in:
Yucheng Zhu 2026-08-26 01:13:56 -07:00
parent 50ef3da304
commit 093bb642cf
7 changed files with 146 additions and 20 deletions

View file

@ -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:

View file

@ -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

View file

@ -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 = (

View file

@ -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):

View file

@ -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
)

View file

@ -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",

View file

@ -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")