From 66980bbb873b4db3d6fd070bc8471feae52efe26 Mon Sep 17 00:00:00 2001 From: Kerry Lu Date: Fri, 11 Sep 2026 12:40:25 -0700 Subject: [PATCH] test(e2e): address Redis chaos PR review, add log-bytes budget Pad the locust payload to tens of KB so per-request bookkeeping cost scales with body size instead of hiding behind a 40-byte prompt. Turn on use_redis_transaction_buffer in the chaos config and JSON_LOGS in the workflow so the spend buffer, pod lock, and JSON-encoded breaker tracebacks are all part of the measured chaos cost. Add a log-bytes-per-request budget alongside latency, RSS, and CPU, reading the proxy's log file size at each phase split; its ceiling is uncalibrated since no chaos run has measured it yet. Co-Authored-By: Claude Code --- .github/workflows/test-e2e-redis-chaos.yml | 2 + tests/e2e/CLAUDE.md | 2 +- tests/e2e/gateway/redis_chaos_ci_config.yml | 1 + tests/e2e/load/locustfile.py | 7 ++- tests/e2e/load/test_redis_chaos_e2e.py | 59 ++++++++++++++++++--- 5 files changed, 62 insertions(+), 9 deletions(-) diff --git a/.github/workflows/test-e2e-redis-chaos.yml b/.github/workflows/test-e2e-redis-chaos.yml index 2ce20836db7..0880c1fb464 100644 --- a/.github/workflows/test-e2e-redis-chaos.yml +++ b/.github/workflows/test-e2e-redis-chaos.yml @@ -40,6 +40,7 @@ jobs: DATABASE_URL: postgresql://llmproxy:dbpassword9090@localhost:5432/litellm LITELLM_MASTER_KEY: sk-redis-chaos-e2e LITELLM_LOG: WARNING + JSON_LOGS: "true" steps: - uses: actions/checkout@08eba0b27e820071cde6df949e0beb9ba4906955 # v4.3.0 with: @@ -73,6 +74,7 @@ jobs: run: | nohup uv run --no-sync litellm --config tests/e2e/gateway/redis_chaos_ci_config.yml --port 4000 --num_workers 4 > proxy.log 2>&1 & echo "E2E_PROXY_PID=$!" >> "$GITHUB_ENV" + echo "E2E_PROXY_LOG=$(pwd)/proxy.log" >> "$GITHUB_ENV" for _ in $(seq 1 90); do if curl -fs http://localhost:4000/health/liveliness > /dev/null; then exit 0 diff --git a/tests/e2e/CLAUDE.md b/tests/e2e/CLAUDE.md index 80e78dd4cdd..ed57dd71759 100644 --- a/tests/e2e/CLAUDE.md +++ b/tests/e2e/CLAUDE.md @@ -18,7 +18,7 @@ Each subdirectory under `tests/e2e/` is one suite, scoped to an endpoint family - `logging/` - logging-integration delivery (datadog and friends) - `security/` - secret handling and log-leak protection - `router/` - routing and reliability behavior (fallbacks, cooldowns) -- `load/` - performance-category tests, kept OUT of the main suite: throughput/load SLO tests are a different testing category from functional e2e (variance-driven, historically flaky) and live outside this suite until re-implemented as their own pipeline (LIT-5163); do not add a live load test that runs in the default collection. What lives here: the weekly session-anomaly test (`test_weekly_session_anomaly_e2e.py`, Claude Code-shaped multi-turn sessions against real providers with ceilings on error rate, cache read/write, turn time, and spend; marked `weekly` and deselected unless `E2E_WEEKLY_ANOMALY` is set, driven by `.github/workflows/weekly_load_anomaly.yml`), the Redis chaos test (`test_redis_chaos_e2e.py`, locust load against mock deployments split round robin over `/chat/completions` and `/v1/messages`, one endpoint per simulated user, with `CLIENT PAUSE ALL` on the proxy's Redis mid-run to simulate it being down outright, asserting zero failed requests on every endpoint and budgeting p50/p90/p99 latency, RSS, and CPU-per-request as ratios against the same run's healthy phase; needs a proxy booted from `gateway/redis_chaos_ci_config.yml` on the same host with `E2E_PROXY_PID` set, marked `redis_chaos`, deselected unless `E2E_REDIS_CHAOS` is set, driven weekly by `.github/workflows/test-e2e-redis-chaos.yml`), and markerless harness unit tests for the locust, process-usage, and session-anomaly aggregation logic +- `load/` - performance-category tests, kept OUT of the main suite: throughput/load SLO tests are a different testing category from functional e2e (variance-driven, historically flaky) and live outside this suite until re-implemented as their own pipeline (LIT-5163); do not add a live load test that runs in the default collection. What lives here: the weekly session-anomaly test (`test_weekly_session_anomaly_e2e.py`, Claude Code-shaped multi-turn sessions against real providers with ceilings on error rate, cache read/write, turn time, and spend; marked `weekly` and deselected unless `E2E_WEEKLY_ANOMALY` is set, driven by `.github/workflows/weekly_load_anomaly.yml`), the Redis chaos test (`test_redis_chaos_e2e.py`, locust load against mock deployments split round robin over `/chat/completions` and `/v1/messages`, one endpoint per simulated user, with `CLIENT PAUSE ALL` on the proxy's Redis mid-run to simulate it being down outright, asserting zero failed requests on every endpoint and budgeting p50/p90/p99 latency, RSS, CPU-per-request, and log-bytes-per-request as ratios against the same run's healthy phase; needs a proxy booted from `gateway/redis_chaos_ci_config.yml` on the same host with `E2E_PROXY_PID` and `E2E_PROXY_LOG` set, marked `redis_chaos`, deselected unless `E2E_REDIS_CHAOS` is set, driven weekly by `.github/workflows/test-e2e-redis-chaos.yml`), and markerless harness unit tests for the locust, process-usage, and session-anomaly aggregation logic - `other/` - the holding-pen suite for the `other.*` registry cluster with no home of its own yet: the master-key auth gate and the process-lifecycle health probes (liveness, public readiness, authenticated readiness diagnostics). Promote a cluster out once it is large/stable enough for its own suite - `gateway/` - proxy configuration only (`litellm-config.yml`); no tests - `claude_code/` - the Claude Code compatibility matrix: drives the real `claude` CLI (and HTTP probes) against a proxy for each feature x provider cell, reporting tagged-union outcomes via the `compat_result` fixture; ships its own driver/builder/publisher plus `_*_unit_tests/` trees. The HTTP probes ride the shared transport (`ProxyClient.count_tokens` / `ProxyClient.messages`); the CLI-driving path stays bespoke diff --git a/tests/e2e/gateway/redis_chaos_ci_config.yml b/tests/e2e/gateway/redis_chaos_ci_config.yml index 37b024502f7..f7a71c50a71 100644 --- a/tests/e2e/gateway/redis_chaos_ci_config.yml +++ b/tests/e2e/gateway/redis_chaos_ci_config.yml @@ -1,6 +1,7 @@ general_settings: master_key: os.environ/LITELLM_MASTER_KEY store_model_in_db: true + use_redis_transaction_buffer: true litellm_settings: callbacks: ["prometheus"] diff --git a/tests/e2e/load/locustfile.py b/tests/e2e/load/locustfile.py index a4e396aa8d7..9b7bdf2ee1e 100644 --- a/tests/e2e/load/locustfile.py +++ b/tests/e2e/load/locustfile.py @@ -11,17 +11,20 @@ from locust import FastHttpUser, constant, task _MODEL: Final = os.environ["LOAD_MODEL"] _API_KEYS: Final = tuple(os.environ["LOAD_API_KEYS"].split(",")) _NEXT_ENDPOINT: Final = cycle(os.environ["LOAD_ENDPOINTS"].split(",")) +_FILLER: Final = "x" * 40_000 def _payload() -> dict[str, object]: """A prompt no other request sent, so the response cache never answers for the deployment. Both endpoints take the same body: /v1/messages requires max_tokens, which /chat/completions - also accepts, so one payload serves the whole round robin. + also accepts, so one payload serves the whole round robin. Padded to tens of KB so a + per-request bookkeeping cost that scales with body size (string formatting, hashing) shows + up in the CPU and log-size budgets instead of hiding behind a 40-byte prompt. """ return { "model": _MODEL, - "messages": [{"role": "user", "content": f"load test ping {uuid.uuid4().hex}"}], + "messages": [{"role": "user", "content": f"load test ping {uuid.uuid4().hex} {_FILLER}"}], "max_tokens": 16, } diff --git a/tests/e2e/load/test_redis_chaos_e2e.py b/tests/e2e/load/test_redis_chaos_e2e.py index 646429bbdd7..153be656566 100644 --- a/tests/e2e/load/test_redis_chaos_e2e.py +++ b/tests/e2e/load/test_redis_chaos_e2e.py @@ -22,11 +22,13 @@ Every touchpoint times out: the auth cache read falls back to Postgres, the resp read and write both fail, and the spend counter increment times out and the callback stringifies the request metadata, breadcrumbs included, into a failed-tracking alert. On v1.100.0 that string doubled per request until the worker hung (LIT-6780), which is what the -per-phase RSS and CPU percentiles are here to catch. +per-phase RSS, CPU, and log-bytes budgets are here to catch. Needs the proxy on the same host, since RSS and CPU come from psutil on its process tree: a multi-worker proxy serves /metrics from the prometheus multiprocess collector, which drops -the process collector's memory and CPU series. Deselected unless E2E_REDIS_CHAOS is set. +the process collector's memory and CPU series. Log bytes are read from the file the proxy's +stdout/stderr was redirected to, so the same host requirement covers that too. Deselected +unless E2E_REDIS_CHAOS is set. """ from __future__ import annotations @@ -37,6 +39,7 @@ import time from collections.abc import Iterator from dataclasses import dataclass from itertools import pairwise +from pathlib import Path from typing import Final import pytest @@ -79,6 +82,11 @@ REDIS_PAUSE_MS: Final = int(CHAOS_SECONDS * 1000) CHAOS_LATENCY_RATIO_CEILING: Final = 12.0 CHAOS_RSS_RATIO_CEILING: Final = 1.5 CHAOS_CPU_PER_REQUEST_RATIO_CEILING: Final = 6.0 +# Uncalibrated: no chaos run has measured this yet, since JSON_LOGS and the padded payload +# landed after the last run this file's other ceilings were calibrated from. Deliberately loose +# until a real run tightens it; the failed-tracking alert body that motivates this test already +# logs the full request metadata per timeout, so a JSON-encoded traceback storm should dwarf this. +CHAOS_LOG_BYTES_PER_REQUEST_RATIO_CEILING: Final = 20.0 DRAIN_TIMEOUT_SECONDS: Final = 30.0 DRAIN_POLL_SECONDS: Final = 1.0 @@ -111,6 +119,7 @@ class Phase: load: LoadResult usage: UsageWindow redis_timeouts: float + log_bytes: int @property def timeouts_per_request(self) -> float: @@ -120,11 +129,16 @@ class Phase: def cpu_seconds_per_request(self) -> float: return self.usage.cpu_seconds_per_request(self.load.requests) + @property + def log_bytes_per_request(self) -> float: + return self.log_bytes / self.load.requests if self.load.requests else 0.0 + def report(self) -> str: return ( f"{self.name}: {self.load.requests} requests, {self.load.failures} failures, " f"{self.load.requests_per_second:.0f} rps, {self.load.latency_summary()}; {self.usage.summary()}; " f"{self.cpu_seconds_per_request * 1000:.1f} ms CPU per request; " + f"{self.log_bytes_per_request:.0f} log bytes per request; " f"{self.timeouts_per_request:.2f} Redis timeouts per request; " f"by endpoint: {self.load.endpoint_summary()}" ) @@ -163,6 +177,22 @@ def proxy_pid() -> int: return int(pid) +@pytest.fixture +def proxy_log() -> Path: + """Path to the proxy's stdout/stderr log, which the workflow captures to a file. + + Required rather than discovered for the same reason as proxy_pid: a developer machine may + have more than one proxy log around. + """ + path: Final = os.environ.get("E2E_PROXY_LOG") + assert path, "E2E_PROXY_LOG must hold the path the proxy's stdout/stderr was redirected to" + return Path(path) + + +def _log_bytes(path: Path) -> int: + return path.stat().st_size + + @pytest.fixture def redis_control() -> Iterator[redis.Redis[bytes]]: """A control connection to the proxy's Redis, which unpauses it in teardown as a safety net. @@ -292,10 +322,13 @@ def _chaos_budgets(baseline: Phase, chaos: Phase) -> tuple[Budget, ...]: tail (or only in the median) cannot hide behind the other. Latency gets the loosest bound because a timing-out Redis legitimately adds its socket_timeout to every request that touches it, several times over on a retried request. RSS gets the tightest: the failure - path has no business allocating more per request. CPU is budgeted once, as CPU seconds per - request rather than per percentile: cores-busy saturates at the worker count under load, so - its percentiles read the same whether a request costs 10 ms of CPU or 40, and cannot budget - anything; seconds per request is the CPU figure that actually moves. + path has no business allocating more per request. CPU and log bytes are each budgeted once, + as an amount per request rather than per percentile: cores-busy saturates at the worker + count under load, so its percentiles read the same whether a request costs 10 ms of CPU or + 40, and cannot budget anything; per-request is the figure that actually moves. Log bytes + isolates the cost of the failed-tracking alert's own noisy error handling from the CPU it + burns doing useful retry work, since the two would otherwise be indistinguishable in one + CPU number. """ return ( _latency_budget("p50", baseline.load.p50_seconds, chaos.load.p50_seconds), @@ -311,6 +344,14 @@ def _chaos_budgets(baseline: Phase, chaos: Phase) -> tuple[Budget, ...]: ratio_ceiling=CHAOS_CPU_PER_REQUEST_RATIO_CEILING, unit=" ms", ), + Budget( + name="log bytes per request", + baseline=baseline.log_bytes_per_request, + degraded=chaos.log_bytes_per_request, + ratio_ceiling=CHAOS_LOG_BYTES_PER_REQUEST_RATIO_CEILING, + unit=" B", + decimals=0, + ), ) @@ -325,6 +366,7 @@ class TestRedisChaos: client: LoadClient, resources: ResourceManager, proxy_pid: int, + proxy_log: Path, redis_control: redis.Redis[bytes], ) -> None: proxy: Final = client.proxy @@ -335,28 +377,33 @@ class TestRedisChaos: cooldown_re: Final = _deployment_metric_re("deployment_cooled_down_total", model_ids) at_start: Final = _scrape(proxy) + log_at_start: Final = _log_bytes(proxy_log) with ProxyUsageSampler(proxy_pid) as sampler: baseline_load: Final = _drive(keys, BASELINE_SECONDS) baseline_usage: Final = sampler.split() after_baseline: Final = _scrape(proxy) + log_after_baseline: Final = _log_bytes(proxy_log) redis_control.client_pause(REDIS_PAUSE_MS, all=True) # pyright: ignore[reportUnknownMemberType] # redis-py stubs return Any chaos_load: Final = _drive(keys, CHAOS_SECONDS) chaos_usage: Final = sampler.split() at_end: Final = _scrape_after_drain(proxy, retries_re) + log_at_end: Final = _log_bytes(proxy_log) baseline: Final = Phase( name="baseline", load=baseline_load, usage=baseline_usage, redis_timeouts=_metric(after_baseline, TIMEOUT_FAILURES_RE) - _metric(at_start, TIMEOUT_FAILURES_RE), + log_bytes=log_after_baseline - log_at_start, ) chaos: Final = Phase( name="chaos", load=chaos_load, usage=chaos_usage, redis_timeouts=_metric(at_end, TIMEOUT_FAILURES_RE) - _metric(after_baseline, TIMEOUT_FAILURES_RE), + log_bytes=log_at_end - log_after_baseline, ) report: Final = f"{baseline.report()} | {chaos.report()}"