test(e2e): make the failure-row test assert, and read spend via /spend/logs/v2

test_failure_call_writes_failure_status_row skipped on every run. It induced the
failure by sending an empty prompt and hoping gemini rejected it; gemini accepts
it, so the test hit 'call unexpectedly succeeded' and skipped, leaving the cell
quota_management.spend_tracking.failure.writes_failure_row counted as covered
while asserting nothing. Induce the failure deterministically instead, with a
throwaway deployment credentialed with an invalid provider key (a guaranteed 401
from the provider), and drop both skips: a failure row that stops being written
is a real regression in the audit trail, not an environment quirk. Verified live:
the rejected call writes exactly one row, status=failure spend=0.0.

Move the spend read-back off /spend/logs onto /spend/logs/v2. /spend/logs is
unbounded and on a long-lived environment answers with the whole spend table; a
58MB response has OOM-killed the e2e runner. v2 takes an explicit window and pages
at 100. It filters on the hashed token as stored on the row rather than the raw
sk- key, which silently matches nothing, so Gateway.hash_token does the sha256 and
poll_logs_for_key keeps taking a raw key: every caller across the six suites that
poll benefits with no change. poll_logs_for_request_id moves too (v2 accepts
request_id). Polls now surface a 5xx instead of swallowing it as 'no rows yet',
since the v2 read unwraps.
This commit is contained in:
mubashir1osmani 2026-07-14 19:42:37 -07:00
parent e3546c20af
commit 24efd82add
3 changed files with 105 additions and 43 deletions

View file

@ -8,11 +8,12 @@ Gateway's key/customer methods for cleanup. Read-backs are eventually consistent
from __future__ import annotations
import hashlib
import time
import warnings
from collections.abc import Callable
from dataclasses import dataclass
from datetime import datetime
from datetime import datetime, timedelta, timezone
from e2e_http import (
NoBody,
@ -50,10 +51,8 @@ from models import (
OcrBody,
OcrResponse,
SpendLogRow,
SpendLogs,
SpendLogsPage,
SpendLogsPageParams,
SpendLogsParams,
)
from e2e_config import (
CONTROL_PLANE_BASE_URL,
@ -245,20 +244,29 @@ class Gateway:
# ---- spend read-back ------------------------------------------------
def spend_logs(self, params: SpendLogsParams) -> list[SpendLogRow]:
result = self.transport.get(
"/spend/logs",
headers=self.transport.master,
params=params,
response_type=SpendLogs,
)
match result:
case Success(data=logs):
return logs.root
case _:
return []
@staticmethod
def hash_token(key: str) -> str:
"""The hashed token as stored on a SpendLogs row: plain sha256 of the raw key.
/spend/logs/v2 filters on this form, not the raw `sk-` value; passing the raw
key silently matches zero rows."""
return hashlib.sha256(key.encode()).hexdigest()
def spend_logs_window(
self,
*,
start: datetime,
end: datetime,
api_key: str | None = None,
request_id: str | None = None,
) -> list[SpendLogRow]:
"""Every row in [start, end], optionally filtered, via paginated /spend/logs/v2.
v2 rather than /spend/logs on purpose: /spend/logs is unbounded, and on a
long-lived environment it answers with the whole table (a 58MB response has
OOM-killed the e2e runner). v2 requires an explicit window and pages at 100.
`api_key` takes the hashed token; use `hash_token` on a raw key first."""
def spend_logs_window(self, *, start: datetime, end: datetime) -> list[SpendLogRow]:
def fetch(page: int) -> SpendLogsPage:
return unwrap(
self.transport.get(
@ -269,6 +277,8 @@ class Gateway:
end_date=end.strftime("%Y-%m-%d %H:%M:%S"),
page=page,
page_size=100,
api_key=api_key,
request_id=request_id,
),
response_type=SpendLogsPage,
)
@ -280,10 +290,24 @@ class Gateway:
*(row for page in range(2, first.total_pages + 1) for row in fetch(page).data),
]
def _run_window(self) -> tuple[datetime, datetime]:
"""A window wide enough to hold anything this run wrote. v2 requires explicit
dates, and the row's timestamp is UTC, so a window built from local "today"
would miss rows that landed on the next UTC day."""
now = datetime.now(timezone.utc)
return now - timedelta(days=1), now + timedelta(days=1)
def poll_logs_for_key(
self, key: str, *, min_rows: int = 1, predicate: RowsPredicate | None = None
) -> list[SpendLogRow]:
return self._poll(lambda: self.spend_logs(SpendLogsParams(api_key=key)), min_rows, predicate)
"""Rows for `key` (raw `sk-` value), polled to the deadline. Reads /spend/logs/v2
under the hashed token; see spend_logs_window for why not /spend/logs."""
start, end = self._run_window()
return self._poll(
lambda: self.spend_logs_window(start=start, end=end, api_key=self.hash_token(key)),
min_rows,
predicate,
)
def poll_logs_for_request_id(
self,
@ -292,8 +316,9 @@ class Gateway:
min_rows: int = 1,
predicate: RowsPredicate | None = None,
) -> list[SpendLogRow]:
start, end = self._run_window()
return self._poll(
lambda: self.spend_logs(SpendLogsParams(request_id=request_id)),
lambda: self.spend_logs_window(start=start, end=end, request_id=request_id),
min_rows,
predicate,
)

View file

@ -269,13 +269,18 @@ class SpendLogsParams(BaseModel):
class SpendLogsPageParams(BaseModel):
"""Query for /spend/logs/v2, which requires an explicit date window and
serves pages of at most 100 rows."""
serves pages of at most 100 rows.
`api_key` filters on the hashed token exactly as stored on the row, not the raw
`sk-` value: passing the raw key matches nothing and returns an empty page rather
than erroring. Use Gateway.hash_token to convert."""
start_date: str
end_date: str
page: int
page_size: int
api_key: str | None = None
request_id: str | None = None
class SpendLogsPage(BaseModel):

View file

@ -18,12 +18,13 @@ fails the test; a pricing or token-count drift does not.
import time
from collections.abc import Callable
from concurrent.futures import ThreadPoolExecutor
from datetime import datetime, timedelta, timezone
import pytest
from e2e_http import Result, Success
from lifecycle import ResourceManager
from models import ChatResponse, SpendLogs, SpendLogsParams
from models import ChatResponse, LiteLLMParamsBody, SpendLogsPage, SpendLogsPageParams
from spend_e2e_client import SpendClient, SpendLogRow, is_ok, unique_marker, unwrap
pytestmark = pytest.mark.e2e
@ -432,22 +433,39 @@ def test_each_model_on_a_shared_key_gets_its_own_row(
@pytest.mark.covers("quota_management.spend_tracking.failure.writes_failure_row")
def test_failure_call_writes_failure_status_row(
client: SpendClient, scoped_key: str
client: SpendClient, resources: ResourceManager
) -> None:
result = client.chat(scoped_key, "gemini-2.5-flash", "", max_tokens=1)
if is_ok(result):
pytest.skip("call unexpectedly succeeded; could not induce a failure row")
"""A call the provider rejects writes a failure-status spend row at zero cost.
The failure is induced deterministically: a throwaway deployment credentialed with
an invalid provider key, so the call is a guaranteed 401 from the provider. The
previous trigger sent an empty prompt and hoped gemini would reject it; gemini
accepts it, so the test skipped on every run and this cell asserted nothing while
still counting as covered. Both skips are gone on purpose - a failure row that
stops being written is a real spend-tracking regression (an un-logged failure is a
hole in the audit trail), not an environment quirk to shrug at."""
model_name = f"e2e-badkey-{unique_marker()}"
model_id = client.gateway.create_model(
model_name,
LiteLLMParamsBody(model="openai/gpt-5.5", api_key="sk-e2e-deliberately-invalid"),
)
resources.defer(lambda: client.gateway.delete_model(model_id))
key = resources.key(models=[model_name])
result = client.chat(key, model_name, "trigger a provider failure", max_tokens=8)
assert not is_ok(
result
), f"a deployment with an invalid provider key must fail, got success: {result}"
rows = client.poll_logs_for_key(
scoped_key, predicate=lambda rs: any(r.status == "failure" for r in rs)
key, predicate=lambda rs: any(r.status == "failure" for r in rs)
)
failure_rows = [r for r in rows if r.status == "failure"]
if not failure_rows:
pytest.skip(
"no failure-status row was logged for the rejected call; "
"failure logging is environment-specific"
)
assert (failure_rows[0].spend or 0) == 0.0, "failed call must not be charged"
row = _require_row(
rows, lambda r: r.status == "failure", "with status=failure for the rejected call"
)
assert (
row.spend or 0
) == 0.0, f"a failed call must not be charged: {_summarize(rows)}"
@pytest.mark.covers("quota_management.spend_tracking.spend_calculate.returns_cost")
@ -464,11 +482,15 @@ def test_spend_calculate_returns_nonzero_cost(client: SpendClient) -> None:
def test_spend_logs_endpoint_returns_spend(
client: SpendClient, scoped_key: str
) -> None:
"""The /spend/logs read endpoint returns a 200 carrying the key's spend, never a
5xx. Regression for intermittent 500s (DB query / serialization errors under load)
on this endpoint: every poll asserts a success response, not just a truthy row
list, so a 500 fails loudly instead of being swallowed as 'no rows yet'; the
call's nonzero spend must surface before the deadline."""
"""The spend read endpoint returns a 200 carrying the key's spend, never a 5xx.
Regression for intermittent 500s (DB query / serialization errors under load): each
poll asserts a success response, not just a truthy row list, so a 500 fails loudly
instead of being swallowed as 'no rows yet'.
Reads /spend/logs/v2, not /spend/logs: the latter is unbounded and on a long-lived
environment answers with the whole spend table, which has OOM-killed the runner.
v2 takes an explicit window and pages, and it filters on the hashed token rather
than the raw sk- key (the raw value silently matches nothing)."""
unwrap(
client.chat(
scoped_key, "gemini-2.5-flash", f"spend logs {unique_marker()}", max_tokens=16
@ -476,21 +498,31 @@ def test_spend_logs_endpoint_returns_spend(
)
gateway = client.gateway
now = datetime.now(timezone.utc)
fmt = "%Y-%m-%d %H:%M:%S"
deadline = time.monotonic() + gateway.poll_timeout
while True:
result = gateway.transport.get(
"/spend/logs",
"/spend/logs/v2",
headers=gateway.transport.master,
params=SpendLogsParams(api_key=scoped_key),
response_type=SpendLogs,
params=SpendLogsPageParams(
start_date=(now - timedelta(days=1)).strftime(fmt),
end_date=(now + timedelta(days=1)).strftime(fmt),
page=1,
page_size=100,
api_key=gateway.hash_token(scoped_key),
),
response_type=SpendLogsPage,
)
assert isinstance(result, Success), f"/spend/logs did not return 200 OK: {result}"
rows = result.data.root
assert isinstance(
result, Success
), f"/spend/logs/v2 did not return 200 OK: {result}"
rows = result.data.data
if sum((r.spend or 0) for r in rows) > 0:
return
if time.monotonic() >= deadline:
pytest.fail(
f"/spend/logs never surfaced the key's spend before the deadline; "
f"/spend/logs/v2 never surfaced the key's spend before the deadline; "
f"saw {_summarize(rows)}"
)
time.sleep(gateway.poll_interval)