From 24efd82adddf023d2675f18d15e55e3791008edb Mon Sep 17 00:00:00 2001 From: mubashir1osmani Date: Tue, 14 Jul 2026 19:42:37 -0700 Subject: [PATCH] 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. --- tests/e2e/e2e_gateway.py | 61 +++++++++----- tests/e2e/models.py | 7 +- .../spend_tracking/test_spend_tracking_e2e.py | 80 +++++++++++++------ 3 files changed, 105 insertions(+), 43 deletions(-) diff --git a/tests/e2e/e2e_gateway.py b/tests/e2e/e2e_gateway.py index d40b96d60fa..c677252d086 100644 --- a/tests/e2e/e2e_gateway.py +++ b/tests/e2e/e2e_gateway.py @@ -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, ) diff --git a/tests/e2e/models.py b/tests/e2e/models.py index bf90426188f..3f8431c2e90 100644 --- a/tests/e2e/models.py +++ b/tests/e2e/models.py @@ -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): diff --git a/tests/e2e/quota_management/spend_tracking/test_spend_tracking_e2e.py b/tests/e2e/quota_management/spend_tracking/test_spend_tracking_e2e.py index 2f0ffae44e3..c6785281683 100644 --- a/tests/e2e/quota_management/spend_tracking/test_spend_tracking_e2e.py +++ b/tests/e2e/quota_management/spend_tracking/test_spend_tracking_e2e.py @@ -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)