From 2d7e5999b78f726c97a7142231de566d788d4fc0 Mon Sep 17 00:00:00 2001 From: Kerry Lu Date: Wed, 9 Sep 2026 16:26:03 -0700 Subject: [PATCH] test(e2e): pause Redis writes for the run and prove the timeouts from /metrics A loopback Redis answers many commands inside the 1 ms socket timeout, so nothing guaranteed the failure path ran. The test now holds the proxy's Redis in CLIENT PAUSE WRITE for its duration, so every write the proxy sends, the spend counter increment included, outlives the timeout, and lifts the pause in teardown. Reads stay live so the control connection can do that. Enable the prometheus callback in the gateway config and assert from /metrics that the proxy counted at least the breaker's five timeouts and that, during each case, it saw fresh timeouts, a breaker transition, or an open breaker rejecting every call. The open breaker is the state a customer's worker sits in, and cost tracking fails on every request either way. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_014ZDULyJPp17ZFiJenRxs2T --- .github/workflows/test-e2e-redis-timeout.yml | 2 + tests/e2e/gateway/redis_timeout_ci_config.yml | 2 + tests/e2e/router/test_redis_timeout_e2e.py | 60 +++++++++++++++++-- 3 files changed, 60 insertions(+), 4 deletions(-) diff --git a/.github/workflows/test-e2e-redis-timeout.yml b/.github/workflows/test-e2e-redis-timeout.yml index a956ed79590..9c318a1346c 100644 --- a/.github/workflows/test-e2e-redis-timeout.yml +++ b/.github/workflows/test-e2e-redis-timeout.yml @@ -86,6 +86,8 @@ jobs: env: E2E_REDIS_TIMEOUT: "1" LITELLM_PROXY_URL: http://localhost:4000 + REDIS_HOST: 127.0.0.1 + REDIS_PORT: "6379" run: | uv run --no-sync pytest tests/e2e/router/test_redis_timeout_e2e.py -v --tb=short -rA diff --git a/tests/e2e/gateway/redis_timeout_ci_config.yml b/tests/e2e/gateway/redis_timeout_ci_config.yml index 735285adb36..375a51f6127 100644 --- a/tests/e2e/gateway/redis_timeout_ci_config.yml +++ b/tests/e2e/gateway/redis_timeout_ci_config.yml @@ -3,6 +3,8 @@ general_settings: store_model_in_db: true litellm_settings: + callbacks: ["prometheus"] + require_auth_for_metrics_endpoint: false cache: true cache_params: type: redis diff --git a/tests/e2e/router/test_redis_timeout_e2e.py b/tests/e2e/router/test_redis_timeout_e2e.py index d10f32b6482..e99bd2fbe80 100644 --- a/tests/e2e/router/test_redis_timeout_e2e.py +++ b/tests/e2e/router/test_redis_timeout_e2e.py @@ -1,8 +1,10 @@ """Live e2e: the proxy keeps answering while every Redis command times out. Runs only against a proxy booted from tests/e2e/gateway/redis_timeout_ci_config.yml, which -points cache_params at a real Redis with socket_timeout 0.001 so commands time out and the -circuit breaker opens. Each request fails its primary deployment, whose api_base is a closed +points cache_params at a real Redis with socket_timeout 0.001. The test holds that Redis in +CLIENT PAUSE WRITE for its duration, so every write the proxy sends, the spend counter increment +included, hangs past the timeout, and it proves the degradation was real from the breaker metrics on /metrics: fresh timeouts, a breaker transition, +or an already-open breaker rejecting every call, which is the state a customer's worker sits in. Each request fails its primary deployment, whose api_base is a closed port, retries, falls back to the backup and succeeds, so it carries retry breadcrumbs; its cost tracking then fails on the spend counter increment and stringifies the request metadata into a failed-tracking alert. On v1.100.0 that string doubled per request until the worker hung @@ -11,12 +13,15 @@ failed-tracking alert. On v1.100.0 that string doubled per request until the wor from __future__ import annotations +import os +import re import time -from collections.abc import Callable +from collections.abc import Callable, Iterator from dataclasses import dataclass from typing import Final import pytest +import redis from complexity_router_client import ComplexityRouterClient from e2e_config import unique_marker from e2e_http import NoBody, Result, Success @@ -33,6 +38,11 @@ REQUESTS: Final = 20 MAX_SECONDS_PER_REQUEST: Final = 10.0 MAX_LATENCY_GROWTH_RATIO: Final = 3.0 MAX_LIVELINESS_SECONDS: Final = 2.0 +REDIS_PAUSE_MS: Final = 600_000 +BREAKER_FAILURE_THRESHOLD: Final = 5 +TIMEOUT_FAILURES_RE: Final = re.compile( + r'^litellm_redis_circuit_breaker_failures_total\{failure_class="timeout"\} ([0-9.e+]+)$', re.M +) class ResponsesBody(BaseModel): @@ -86,6 +96,32 @@ ENDPOINTS: Final = ( served=lambda data: isinstance(data, ResponsesObject) and bool(data.output), ), ) +BREAKER_OPEN_RE: Final = re.compile(r'^litellm_redis_circuit_breaker_state\{state="open"\} ([0-9.e+]+)$', re.M) +BREAKER_TRANSITIONS_RE: Final = re.compile( + r'^litellm_redis_circuit_breaker_transitions_total\{state="[a-z_]+"\} ([0-9.e+]+)$', re.M +) + + +@pytest.fixture +def paused_redis() -> Iterator[None]: + """Hold the proxy's Redis in CLIENT PAUSE WRITE so every write it sends outlives the 1 ms socket + timeout. A loopback Redis otherwise answers many commands inside that budget. Reads stay live so + this control connection can lift the pause in teardown.""" + host = os.environ.get("REDIS_HOST") + port = os.environ.get("REDIS_PORT") + assert host and port, "REDIS_HOST and REDIS_PORT must name the Redis the proxy under test uses" + control = redis.Redis(host=host, port=int(port), socket_timeout=5) + control.client_pause(REDIS_PAUSE_MS, all=False) # pyright: ignore[reportUnknownMemberType] # redis-py stubs return Any + try: + yield + finally: + control.client_unpause() # pyright: ignore[reportUnknownMemberType] # redis-py stubs return Any + control.close() + + +def _metric(proxy: ProxyClient, pattern: re.Pattern[str]) -> float: + body = proxy.probe("/metrics", params=NoBody()).body + return sum(float(match.group(1)) for match in pattern.finditer(body)) class TestRedisTimeout: @@ -95,9 +131,11 @@ class TestRedisTimeout: exercised_on=["chat_completions", "responses"], ) def test_retries_under_redis_timeouts_keep_answering( - self, client: ComplexityRouterClient, resources: ResourceManager, endpoint: Endpoint + self, client: ComplexityRouterClient, resources: ResourceManager, endpoint: Endpoint, paused_redis: None ) -> None: proxy = client.proxy + timeouts_before = _metric(proxy, TIMEOUT_FAILURES_RE) + transitions_before = _metric(proxy, BREAKER_TRANSITIONS_RE) key = proxy.generate_key( KeyGenerateBody( models=[PRIMARY_MODEL, BACKUP_MODEL], key_alias=f"e2e-redis-timeout-{endpoint.name}-{unique_marker()}" @@ -139,6 +177,20 @@ class TestRedisTimeout: f"/health/liveliness took {liveliness_seconds:.1f}s after the loop; the worker is stalled" ) + timeouts_total = _metric(proxy, TIMEOUT_FAILURES_RE) + timeouts = timeouts_total - timeouts_before + transitions = _metric(proxy, BREAKER_TRANSITIONS_RE) - transitions_before + breaker_open = _metric(proxy, BREAKER_OPEN_RE) >= 1 + assert timeouts_total >= BREAKER_FAILURE_THRESHOLD, ( + f"the proxy counted only {timeouts_total:.0f} Redis timeouts in its lifetime; the write-paused Redis " + "never made its spend counter writes time out, so this run proved nothing" + ) + assert timeouts >= REQUESTS or transitions >= 1 or breaker_open, ( + f"during {REQUESTS} {endpoint.name} requests the breaker counted {timeouts:.0f} new timeouts, " + f"{transitions:.0f} state transitions, and ended {'open' if breaker_open else 'closed'}; " + "Redis was healthy for this case, so it proved nothing" + ) + rows = proxy.poll_logs_for_key(key, min_rows=REQUESTS) assert len(rows) >= REQUESTS, ( f"only {len(rows)} of {REQUESTS} {endpoint.name} requests reached the spend log; "