test: Ollama CI stalls fail the quality matrix in three shapes; #1369 retry covers only one

[planetf1]

Problem

The quality matrix still intermittently fails on the live-Ollama telemetry
tests even after #1318 (mocked tracing coverage) and #1369 (auto-retry on
ReadTimeout). Ollama intermittently stalls requests on the loaded
ubuntu-latest CPU runners, and that stall surfaces as three different
failure shapes — only one of which the current retry net covers.

Observed behaviour

Evidence from completed public runs (all code-checks / quality jobs):

Run	Branch / model	Failed test	Failure shape	Covered by #1369 retry?
32758965363 (2026-08-24, main merge queue, Granite 4.1)	pr-1564	test_ollama_generate_from_raw_metrics_integration	Ollama returned an empty response (response='', done=True, warning from generate_from_raw), no tokens recorded, assert (None is not None)	No — AssertionError matches no pattern
32950575498 (2026-08-26, PR #1587, Granite 4.2)	0c7c9023 predecessor	test_litellm_token_metrics_integration[non-streaming] + 2 native tracing/metrics tests	900 s pytest-timeout watchdog kill (litellm path) + httpx.ReadTimeout ×2 (retries exhausted)	Partially — native ReadTimeout retried, litellm watchdog not
32972890653 (2026-08-26, PR #1587, Granite 4.2)	0c7c9023	test_litellm_token_metrics_integration[non-streaming] + 3 native tracing tests	Same: watchdog kill + 9 consecutive ~300 s httpx.ReadTimeouts (3 tests × 3 attempts)	Partially, as above

Notes:

• The failing tests differ between runs on the same SHA set (different
  tracing tests fail each time), consistent with a nondeterministic
  server-side stall rather than a test defect. In run 32972890653 the same
  model served requests in 2–77 s immediately before and after a ~45-minute
  stall window, with slow-but-passing calls at 173 s and 242 s bracketing
  the native backend's 300 s timeout.
• The litellm watchdog shape is mechanical, not just bad luck:
  LiteLLMBackend passes no request deadline to litellm.acompletion, so
  litellm falls back to a 600 s per-attempt timeout, the OpenAI SDK
  silently retries a stalled attempt (verified: 3 attempts against a stalled
  socket), and only_rerun="ReadTimeout" never matched the litellm path's
  litellm.exceptions.Timeout (message embeds APITimeoutError). A single
  stall therefore consumed the whole per-attempt budget with no retry.
• Server-side cause of the stalls is unknown: the quality workflow ran
  nohup ollama serve & without capturing output, so job logs contained
  zero server lines across the ~90-minute test window.

Expected behaviour

• A stalled live-Ollama request should surface as a bounded, retryable
  timeout on every backend path, and the run should be diagnosable from the
  job log without re-implementing the server-side investigation.

Reproduce

Run the quality workflow repeatedly on a Granite live-test branch (CPU
runners, Ollama 0.32.2). Stalls occur intermittently; runs 32950575498 /
32972890653 above are fixed records of the failure shapes.

Already addressed by PR #1587

• The litellm live test is bounded to the same 300 s the native
  OllamaModelBackend uses, with num_retries: 0, so one pytest attempt
  can no longer exceed the 900 s watchdog budget.
• The flaky marker now retries both timeout shapes
  (OLLAMA_TIMEOUT_RERUN_PATTERNS, regression-pinned in
  test/test_flaky_ollama_rerun.py).
• The workflow captures the Ollama server log and dumps it on failure, so
  the first subsequent red run carries server-side evidence.

Remaining work (tracked here)

1. Diagnose the server-side stall cause from the first red run with server
   logs (memory/page-cache pressure on shared runners, Ollama scheduler
   behaviour, model loading under concurrency).
2. Decide handling for the empty-response shape (seen on main, run
   32758965363): generate_from_raw currently logs a warning and returns an
   empty string, which downstream tests turn into assert None is not None
   — a failure shape no retry pattern can match. Options: retry on the
   empty-response warning, or make the backend surface a typed error.
3. Reassess whether the retry budget (2 reruns) is adequate once the stall
   cause is known, or whether live telemetry tests need a dedicated
   warmup/keep-alive strategy.

Related: #1318 (closed), #1367 (closed), #1369 (merged), #1296, PR #1587.

[planetf1]

Update from PR #1587 — run 32991484037 (SHA c0278730, 2026-08-26, Python 3.11 lane) failed; 3.12/3.13 cancelled by fail-fast. Three things came out of it:

1. The LiteLLM bounded-timeout fix is verified working in CI.
test_litellm_token_metrics_integration[non-streaming] now dies as a bounded 300 s litellm.exceptions.Timeout (APITimeoutError) and is retried — RERUNs at 18:00:30 and 18:05:37, final fail 18:10:39 — instead of a 900 s watchdog kill. It still failed because the Ollama server on the 3.11 runner was stalled for ~31 continuous minutes (17:39–18:10), which outlasts even the new 3×300 s budget.

2. New failure surface: streaming tests hit the 900 s watchdog.
test_ollama_token_metrics_integration[streaming] and test_openai_token_metrics_integration[streaming] were watchdog-killed mid-stream. Both kill stacks show the event loop with the 120 s per-chunk guard still armed (select(timeout=119.998)). The streaming path (send_to_queue, mellea/helpers/async_helpers.py) is guarded only by DEFAULT_CHUNK_TIMEOUT (120 s per inter-chunk gap, aborts the stream when a gap reaches 120 s); there is no total-time bound. A slow or trickling stream whose gaps all stay under 120 s can therefore consume the entire 900 s pytest-timeout budget in a single request. The non-streaming paths have a hard 300 s httpx bound; the streaming path does not. Fixing that (e.g. a total stream-time cap) is a library design change — adding it to the remaining-work list below.

3. First server-side evidence captured (and the dump needs one more fix).
The new failure-time server-log dump ran, but a plain tail -n 100 covers only ~30 s of Ollama's verbose output (slot print_timing lines every ~25 tokens) and missed the stall window. What it did show (18:42–18:46, after recovery): the server slow but functional — a 51.4 s /api/chat, then a request decoding 1865 tokens at ~9 t/s over 3 m 33 s (truncated = 0). Follow-up commit 0fb41929 changes the dump to the whole-run request-level story (one GIN line per HTTP request with duration, plus error/warning and load/unload lines), so the next red run will show what the server was doing during the stall itself.

Remaining work, updated:

1. Diagnose the server-side stall → in progress: the improved dump lands with 0fb41929; first stall-window evidence expected on the next red run.
2. Decide the empty-response shape (run 32758965363) — still open.
3. Reassess the retry budget — still open (a 31-minute stall exhausts 3×300 s).
4. New: consider a total-time bound for the streaming path (per-chunk guard only today).

[planetf1]

Update from PR #1587 — two more runs, and the streaming failure is now fully characterised.

Run 33015176815 (SHA 41d42beb): the output-cap + TimeoutError-retry fix took the 3.11 lane green. That is the first green lane in this sequence. 3.13 still failed, but only on test_openai_token_metrics_integration[streaming] (900 s watchdog) plus test_multiple_generations_separate_spans (httpx.ReadTimeout, already covered by the retry net).

The improved whole-run GIN dump works and pins the streaming mechanism. The server log for the failing 3.13 lane shows requests completing at exactly 15m0s (200) and 5m0s (500) — round numbers are timeout artifacts, not natural generation. The failing openai-streaming request held its connection open for the full 900 s; the server completed it at the same second the pytest watchdog fired. So the shape is: a stalled or queued stream keeps the HTTP connection alive, which keeps the 120 s per-chunk guard (send_to_queue, mellea/helpers/async_helpers.py) re-armed, and with no total-time bound the client rides straight to the 900 s watchdog. The 64-token output cap cannot help here because the stall is before/around decoding, not in generation length. This is the same class as the non-streaming stall, but the streaming path has no 300 s bound the way httpx does for non-streaming.

PR-side mitigation landed (test-scoped, 36258b04): the four live streaming telemetry tests now consume the stream under asyncio.wait_for(..., timeout=300.0), mirroring the non-streaming bound. A genuine stall now surfaces as a bounded builtin TimeoutError the flaky marker retries; on a healthy runner the stream finishes in seconds so the wrapper is a no-op. This keeps the PR's job green-with-retries without changing library behaviour.

Remaining work, updated:

1. Diagnose the server-side stall → the whole-run GIN dump now captures request-level timing; the stall is reproduced as round-number (300 s / 900 s) server-side timeouts on the CI runner.
2. Decide the empty-response shape (run 32758965363) — still open.
3. Reassess the retry budget — still open (a 31-minute stall exhausts 3×300 s).
4. Library decision: add a total-time bound to the streaming path (per-chunk guard only today). The PR currently papers over this test-side with wait_for; a ModelOption-level stream total-time cap would be the durable fix and would let the test wrapper be removed.

[planetf1]

Update from PR #1587 — run 33039206380 (SHA 36258b04, 2026-08-27).

The streaming failure class is resolved. All four live streaming telemetry tests passed, including test_openai_token_metrics_integration[streaming], which was watchdog-killed on the two prior 3.13 lanes. The 300 s total-stream bound (test-side asyncio.wait_for) plus the 64-token cap did the job.

The 3.11 lane red is the retry-budget class, now with a full stall-window capture. Single failure: test_tracing_backend.py::test_context_propagation_parent_child (httpx.ReadTimeout). The whole-run GIN timeline shows the 3.11 runner's Ollama server accepting requests it never serviced from ~05:05 to ~05:50 — repeated 500 | 5m0s | POST /api/chat (one per test attempt, each a 300 s server-side abort), with a single 2 m 11 s recovery in the middle. The flaky retry net retried exactly as designed (RERUNs at 05:17:43 and 05:22:48); the ~45-minute continuous stall simply outlasts the 3×300 s budget.

This sharpens item 3: with the stall window now measurable (31 min on run 32991484037, ~45 min here), the retry budget question is concrete — either more attempts, longer per-attempt bounds, or a server-side fix (the 300 s abort-with-500 behaviour and the multi-minute stalls are the server/runner problem).

[planetf1]

Update from PR #1587 — rerun of 33039206380 (SHA 36258b04, 3.11 lane) failed on a fourth failure shape, and the whole-run GIN timeline pinned its mechanism exactly.

The OpenAI SDK auto-retry chain multiplies the per-attempt bound past the 900 s watchdog. test_openai_token_metrics_integration[non-streaming] was watchdog-killed at 900 s. Server timeline: the request stalled, the client's 600 s httpx read timeout fired at exactly 10m0s (Ollama logged the client disconnect as 500 | 10m0s | POST /v1/chat/completions), the SDK then auto-retried the 5xx with its default max_retries=2, and the second attempt (500 | 4m59s) was still in flight when the watchdog killed the test. 600 s + 600 s > 900 s, so the chain cannot complete inside one attempt.

This is the SDK's default behaviour, not a mellea one: the OpenAI-compatible path (OpenAIBackend) passes client kwargs through to openai.OpenAI, but nothing in the live tests (or the defaults) disables retries or shortens the 600 s read timeout. Fixed in PR commit 5aab00a6 by setting max_retries=0, timeout=300.0 on the test's client (mirroring the litellm test's timeout=300.0 + num_retries=0); a stalled server now yields one bounded, retryable error per attempt.

Remaining work, updated:

1. Server-side stall behaviour: now captured with per-request timing across four runs (31 min continuous on 32991484037; ~45 min on the first pass of 33039206380; discrete 300 s/600 s aborts elsewhere). The 300 s abort-with-500 and the multi-minute stalls are the server/runner problem.
2. Decide the empty-response shape (run 32758965363) — still open.
3. Reassess the retry budget — now with two measurable stall windows (31 min, ~45 min) both exceeding 3×300 s.
4. Library decision: total-time bound for the streaming path (the PR's wait_for wrapper is test-side only).
5. New: document/review the OpenAI SDK auto-retry interaction on the OpenAI-compatible path — a consumer using OpenAIBackend against a flaky OpenAI-compatible server inherits the default 2-retry × 600 s chain; a max_retries/timeout note (or default) may be worth a doc or issue.

[planetf1]

Status update from #1587 (now merge-ready, CI green on the current head):

Fixed by #1587:

• Shape 2 (litellm 900 s watchdog kill) — not just mitigated, root-caused: granite4.2 thinks by default, and mellea's OpenAI-compatible backends had no way to turn it off on Ollama's /v1 endpoint (the vLLM chat_template_kwargs.enable_thinking convention is ignored there). A 64-token capped reply was ~45 thinking tokens — enough to blow the 300 s cap whenever the CI runner ran 2–3x slower than nominal. Fix: THINKING: False now also sends reasoning_effort="none" (Ollama >= 0.33.1), scoped away from real api.openai.com. Bounded timeout + num_retries: 0 (already noted in this issue) plus the retry-pattern fix stand as before.
• Two further stall causes found during this PR's own CI debugging, not in the original three shapes:
  • Two live telemetry tests built their prompt on SimpleContext (view_for_generation() always []), so the model received an empty conversation — granite4.2 rambles 2000+ tokens on empty input. Fixed by switching those tests to ChatContext.
  • Ollama 0.33.1 (x86) can ignore num_predict after a context-size-mismatch runner reload. Worked around by pinning num_ctx=8192 everywhere in CI and warming up each model at the context its tests use.

NOT fixed by #1587 — still open:

• Shape 1 (empty response from generate_from_raw, run 32758965363 on main/Granite 4.1) — no evidence this PR's changes touch that mechanism. test_ollama_generate_from_raw_metrics_integration was switched SimpleContext → ChatContext for consistency with the other live tests, but that test passes its prompt via actions=[CBlock(...)] directly to generate_from_raw, not via context history, so the empty-context bug found elsewhere doesn't apply here — this looks like an independent, genuine Ollama-side empty-completion flake. Still needs the "retry on empty-response, or surface a typed error" decision from the original issue.
• Remaining-work items 1 and 3 (broader server-side stall diagnosis; reassessing the retry budget once the cause is known) are unaffected by feat: add Granite 4.2 model defaults #1587.

Recommend keeping this open — only shape 2 (plus the two new mechanisms) is resolved, shape 1 and the general diagnosis work remain.