Skip to content

Stop the cancel-during-backoff test measuring the machine - #413

Merged
dovvnloading merged 1 commit into
mainfrom
fix/flaky-cancel-backoff-timing
Sep 4, 2026
Merged

Stop the cancel-during-backoff test measuring the machine#413
dovvnloading merged 1 commit into
mainfrom
fix/flaky-cancel-backoff-timing

Conversation

@dovvnloading

Copy link
Copy Markdown
Owner

Problem

test_cancel_during_backoff_aborts_promptly ended with a hard wall-clock
budget:

assert time_module.monotonic() - started < 2.0

It was going red for reasons unrelated to the code. Investigating why found
two problems behind it, neither of them a busy machine.

1. The test made a real network call

Every chat_stream through the ollama_mode fixture asks
_get_ollama_context_window what window the daemon will serve for
"fake-model:1b", and that calls ollama.show() for real — httpx, httpcore,
connect_tcp. No daemon runs in a test environment and none anywhere serves a
model by that name, so it was always going to fail. It just took a ~2.0 second
TCP connect to find out.

cProfile over the test call:

1  0.000  2.020  api_provider.py:1870(_chat_stream_dispatch)
1  0.000  2.020  api_provider.py:780(_get_ollama_context_window)
1  0.000  2.020  ollama/_client.py:657(show)
1  0.000  2.019  httpx/_client.py:879(send)
1  0.000  2.018  httpcore/_backends/sync.py:188(connect_tcp)

2.018 of the 2.020 seconds was the connect. The assertion was measuring it.

The result is cached per process, so that cost lands entirely on whichever
ollama-mode test runs first in a worker. That is what made this look like
load flakiness — under -n auto --dist worksteal the identity of that test
changes run to run:

result
run alone fails 5/5, at 2.05s
run after one sibling ollama-mode test passes in 0.06s, and the 2.07s moves onto the sibling

2. Which guard it covered was decided by the same accident

_transport_retry_wait checks the cancel event, computes its delay, and only
then blocks in event.wait(delay). The test armed a 50ms threading.Timer
against that sequence.

  • When the first attempt paid the 2s connect, the timer always won, the
    pre-wait guard raised, and the interruptible wait the test is named for
    was never entered — traced, 6/6 runs.
  • When the connect was already cached, the attempt took ~60ms and the wait
    was reached — also 6/6.

Both guards are worth covering. Neither was covered on purpose.

Change

The fixture stubs _get_ollama_context_window to return None — exactly what
the failed call returned, so callers still fall back to
_DEFAULT_CONTEXT_WINDOW — and no ollama-mode test opens a socket.

Stubbed at that function rather than at api_provider.ollama, because the
module object is also what the provider and the transient-error classifier
reach through; replacing the whole module with a namespace carrying only
show() silently disables the retry path these tests exercise. I found that
out by doing it that way first — the retry stopped happening and the test
stopped raising.

The test is replaced by two, each pinning one guard, both driven by a scripted
cancel event instead of a timer:

  • test_a_cancel_during_backoff_interrupts_the_wait_instead_of_sleeping_it_out
  • test_a_cancel_before_the_backoff_aborts_without_waiting_at_all

_ScriptedCancelEvent is a duck-typed stand-in — api_provider only ever
calls is_set() and wait() on this object — that cancels on cue rather than
on a clock, and records the timeout each wait() was handed.

Nothing asserts on elapsed time. The during-backoff test asserts the wait was
handed exactly [10.0], the full Retry-After, so it cannot pass because the
delay happened to be negligible; and that time.sleep was never called, which
is what "interruptible" means here.

Verification

Both mutations applied via monkeypatch, not to the file:

mutation new test old test
cancellable branch → plain time.sleep fails caught it, but only on a warm cache; on a cold one it failed identically either way
Retry-After stops raising the delay fails, [1.2085877752862941] == [10.0] could never see it — a backoff collapsing to the jittered base would have made it pass faster

Test plan

  • Full suite: 3,247 passed, 19 skipped.
  • The two new tests pass 8/8 run alone on a cold cache, where the old one
    failed 5/5.
  • ruff check . clean.
  • No suite speedup to report: the connect is once per process and invisible in
    a 130s file run (131.4s after vs 129.6s before). It only mattered because it
    was charged to a test that asserted on its own wall clock.

🤖 Generated with Claude Code

test_cancel_during_backoff_aborts_promptly ended with a hard wall-clock
budget:

    assert time_module.monotonic() - started < 2.0

Investigating why it went red found two problems behind it, neither of
them the machine being busy.

FIRST: the test made a real network call. Every chat_stream through the
ollama_mode fixture asks _get_ollama_context_window what window the daemon
will serve for "fake-model:1b", and that calls ollama.show() for real -
httpx, httpcore, connect_tcp. No daemon runs in a test environment and none
anywhere serves a model by that name, so it was always going to fail; it
just took a ~2.0s TCP connect to find out. cProfile over the test call:
2.018s of the 2.020s was that connect. The assertion was measuring it.

The result is cached per process, so the cost lands entirely on whichever
ollama-mode test runs first in a worker. That is what made this look like
load flakiness: under `-n auto --dist worksteal` the identity of that test
changes run to run. Run alone it failed 5/5 at 2.05s; run after one sibling
ollama-mode test it passed in 0.06s, with the 2.07s moved onto the sibling.

SECOND: which of the two cancellation guards the test covered was decided
by the same accident. _transport_retry_wait checks the event, computes its
delay, then blocks in event.wait(delay), and the test armed a 50ms timer
against that sequence. When the first attempt paid the 2s connect the timer
always won, the PRE-wait guard raised, and the interruptible wait the test
is named for was never entered - traced, 6/6 runs. When the connect was
already cached the attempt took ~60ms and the wait was reached instead -
also 6/6. Both guards are worth covering; neither was covered on purpose.

The fixture now stubs _get_ollama_context_window to return None - exactly
what the failed call returned, so callers still fall back to
_DEFAULT_CONTEXT_WINDOW - and no ollama-mode test opens a socket. Stubbed
at that function rather than at api_provider.ollama, because the module
object is also what the provider and the transient-error classifier reach
through; replacing the whole module with a namespace carrying only show()
silently disables the retry path these tests exercise. (Found by doing it
that way first: the retry stopped happening and the test stopped raising.)

The test is replaced by two, each pinning one guard, both driven by a
scripted cancel event rather than a timer:

  test_a_cancel_during_backoff_interrupts_the_wait_instead_of_sleeping_it_out
  test_a_cancel_before_the_backoff_aborts_without_waiting_at_all

Nothing asserts on elapsed time. The during-backoff test asserts the wait
was handed exactly [10.0] - the full Retry-After, so it cannot pass because
the delay happened to be negligible - and that time.sleep was never called,
which is what "interruptible" means here.

Verified by mutation, both applied via monkeypatch rather than to the file:
 - Replacing the cancellable branch with a plain time.sleep: the new test
   fails. The old test also caught this, but only on a warm cache; on a
   cold one it failed identically either way.
 - Making Retry-After stop raising the delay: the new test fails with
   [1.2085877752862941] == [10.0]. The old test could never see this - a
   backoff that collapsed to the jittered base would have made it pass
   faster.

Test plan: full suite, 3,247 passed / 19 skipped. The two new tests pass
8/8 run alone on a cold cache, where the old one failed 5/5. ruff clean.
No suite speedup to report: the connect is once per process and invisible
in a 130s file run - it only mattered because it was charged to a test that
asserted on its own wall clock.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@dovvnloading
dovvnloading merged commit 992314e into main Sep 4, 2026
5 checks passed
@dovvnloading
dovvnloading deleted the fix/flaky-cancel-backoff-timing branch September 4, 2026 17:55
dovvnloading added a commit that referenced this pull request Sep 4, 2026
…415)

* Stop the test suite phoning a real Ollama daemon

PR #413 fixed one test that opened a TCP connection to 127.0.0.1:11434 and
noted nine other files that set OLLAMA_MODELS the same way but had not been
checked. Instrumenting socket.connect across a full run answered it: the
suite made 102 outbound connects to that port.

  46x  _get_ollama_capabilities  <- ollama_supports_tools
  46x  _get_ollama_capabilities  <- ollama_supports_embedding
  10x  _get_ollama_context_window <- _ollama_effective_context_window

#413 only closed the third one, and only inside test_providers.py.

Two things made the other 92 expensive rather than merely wrong. Each
attempt costs a ~2s TCP connect on a machine with nothing listening. And
_get_ollama_capabilities deliberately does not cache a probe failure -
correct in production, where a daemon may simply have been restarting, but
it means every check pays that cost again rather than once.

It was also a quiet correctness problem: a developer running Ollama locally
got different answers out of these three functions than CI did, from the
same code, and nothing in the suite would have shown it.

backend/tests/conftest.py now makes ollama.show raise, next to the existing
_never_touch_the_real_user_data_dir fixture and for the same reason. That
is the same "daemon unavailable" outcome the failed connect produced, minus
the socket. Patched on the real module rather than replacing
api_provider.ollama wholesale, because other code reaches through that
module object for ollama.chat; tests that want their own show()
(test_context_budget.py) override it and still win.

backend/tests/test_no_network_in_tests.py asserts the fixture is working,
phrased as "no socket was opened" rather than "show raised" so it keeps
holding if the probing moves to another client or another function. It also
pins that the stub still answers "unavailable" rather than fabricating a
capability set, and that a test can still supply its own show().

Verified: with the fixture removed, all three socket assertions fail. With
it, a full run makes ZERO outbound connects - the only remaining
socket.connect calls in the suite are asyncio's own Windows self-pipe.

The suite also got faster, which was not the point but is worth recording:
103.2s to 84.0s, about 19%.

Test plan: full suite, 3,285 passed / 20 skipped. ruff clean.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

* Put mypy on the whole tree, and fix a version string that was never read

The last of the type sweep. `mypy backend` went from 179 errors to zero,
and [tool.mypy].files - four files when this audit started - now lists
every Python root in the repo: 339 source files, checked in CI.

WHAT WAS ACTUALLY WRONG, because "179 type errors" is not a description:

api_provider.py held 32 of them and was the module worth the most care.
Four `base_url: str = None` signatures that PEP 484 has prohibited since
2018. Three module-level caches with no declared shape - one of which,
_LLAMA_CPP_CLIENT_CACHE, I first annotated dict[str, Any] and mypy
rejected, because llama_cpp_runtime keys it by a five-tuple. LLAMA_CPP_
SETTINGS inferred as dict[str, object] from its mixed literal, which made
every .get() on it unusable at the far end and accounted for most of
provider_runtime's errors too. And three "Missing return statement" reports
that were all one thing: _translate_chat_exception's docstring says
"Always raises ... never returns normally", which is exactly what NoReturn
is for.

A REAL BUG, found by the types and fixed here. backend/harness/
transcript.py did `from graphlink_version import __version__`. There is no
__version__ - graphlink_version.py holds one line, APP_VERSION - and the
name appears nowhere else in the repo. The import raised ImportError on
every call, the surrounding `except Exception` swallowed it, and every
harness transcript ever written recorded "app": "" instead of the version
that field exists to record. about.py, diagnostic_bundle.py and
workspace_archive.py all import the right name. Verified before and after:
the meta record now says v1.0.8.

THE ONE COERCION, called out because it is the only line here that changes
what runs: AnthropicProvider and GeminiProvider take api_key: str, and the
snapshot's api_key is str | None - genuinely, since API_KEY starts as None
and only initialize_api sets it. Eight call sites now pass
`state.api_key or ""`. Both providers store the value verbatim and send it
as a header, so None and "" both end in an auth failure; "" is the one the
type system can describe, and it fails the same way rather than as a
TypeError inside the SDK.

Everything else is annotations, renamed locals that had been reused at two
different types, and containers that never said what they held. 28
`# type: ignore` comments were added and every one carries the invariant it
rests on - sqlite's cursor.lastrowid being Optional only before an INSERT,
the optional-dependency `x = None` fallback, duck-typed attributes whose
declared home is a subclass. I checked each; the reasoning holds in all 28.

backend/knowledge_embeddings.py is worth singling out for what was NOT
done: embed() lives on two of the five providers, so widening the shared
Provider protocol would have broken the other three. It gets a local
two-line protocol and a cast instead, guarded - as it already was - by an
explicit `if not provider.capabilities.embedding: raise` before each call.

[tool.mypy] also gains follow_imports = "silent". Without it, listing a
clean module drags its whole import closure into the gate; with everything
listed it is belt and braces for whatever is added next. Verified the gate
still bites by injecting a deliberate type error into five different
modules - api_provider, session_save, seed_demo_graph, graphlink_desktop,
provider_runtime/reasoning - and it was caught every time.

Test plan: full suite, 3,285 passed / 20 skipped. ruff clean. mypy clean
across 339 source files.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant