Skip to content

Two adagents tests gate on wall-clock budgets and fail under parallel load #1407

Closed

Description

@KonstantinMirin

Two tests in the adagents suite pass or fail on wall-clock timing rather than on behaviour, so they fail under parallel load on a busy runner. One fired on CI today; the other has been observed locally. They are the same defect class, which is why this is one issue.

  • tests/test_adagents_ads_redirects.py::test_off_root_destination_must_not_redirect[https://publisher.com/ads.txt]
  • tests/test_adagents.py::TestGetPropertiesByAgent::test_get_properties_by_agent_cafemedia_scale

The part worth fixing regardless of either test

_fetch_ads_txt_managerdomains catches (asyncio.TimeoutError, httpx.RequestError, AdagentsValidationError) and returns []. That converts a timeout into a false negative indistinguishable from a correct refusal.

Every other "no directives" outcome of that function is a deliberate policy decision — missing Location, a repeated canonical URL, a downgrade to http, unsafe DNS. A starved event loop now produces the identical value, so:

  • the test asserts a behavioural claim — "this off-root destination must not redirect" — when what actually happened is nothing ran;
  • a caller cannot distinguish "the publisher declared no manager" from "we ran out of time";
  • in production, a loaded host silently degrades to "no MANAGERDOMAIN found" instead of surfacing a timeout.

This is why the failure cost a night to diagnose rather than a minute: the symptom is an empty list that looks like a correct answer. Distinguishing the timeout from the policy refusals — even just logging it apart, or returning something a caller can tell apart — is worth doing independently of any test budget.

Mechanism, as a controlled experiment

The work before the first hop is negligible, so the 1-second budget can only expire under event-loop starvation. Reproduced by varying only the budget and the stall:

condition result seen assertion
budget 1s, loop healthy [] 2 passes
budget 1s, loop stalled 1.2s before hop 1 [] 0 fails exactly as CI did
budget 1ms, timeout forced [] 1 passes

The third row is the one that proves the mechanism instead of asserting it: a merely-small timeout still enters the transport factory once, so seen == 1. Only a delay longer than the budget, landing before the first hop, yields seen == [].

Supporting measurements: _validate_publisher_domain and _validate_redirect_url both take 0.000s on first call (the PSL is bundled, no network); the full three-hop walk takes 0.02s in a cold process; the CI job that failed ran 11,596 tests on 2 workers in 11:49.

Where the stall has to land

_follow_ads_txt_redirects computes deadline = asyncio.get_running_loop().time() + timeout at adagents.py:901, strictly locally — there is no cached or module-level deadline, so a delay before the call cannot consume it. Between that line and the first budget check there is exactly one suspension point:

deadline = asyncio.get_running_loop().time() + timeout   # 901
...
await _dns_validate_host(parsed.hostname or "", parsed.port or 443)   # 912  <- the only await
remaining = _ads_txt_remaining(deadline)                              # 913  <- raises TimeoutError
async with factory(current_url, remaining) as owned_client:           # factory entered here

_ads_txt_remaining raises asyncio.TimeoutError("ads.txt redirect deadline exceeded") when deadline - loop.time() <= 0, and the factory — the thing that appends to seen — is entered only after it. So seen == [] localises to that single raise, and the stall must occur at the line-912 await.

A note on reading the CI log, because it is misleading: under -n 2 -v the bare test-id line and the [gwN] STATUS line are both printed by the controller when one report arrives. Measured locally on this same output format they are 0.0002–0.0005s apart, so that separation is print time and not test duration — the test's real execution time appears as the gap before those two lines. Anyone reading the stream literally will conclude the body ran in under a millisecond, which it did not.

Why it surfaced now, and why it will recur

CI runs -n 2 --dist=loadfile, which assigns whole files to workers. Adding any test file reshuffles the file-to-worker grouping and therefore what a timing-sensitive test runs alongside. There is no pytest-randomly in the plugin list, so ordering is otherwise deterministic — which means the next person to add a test file to this suite draws a different ticket, and the symptom (seen == []) will give them no hint that timing is involved.

Nothing about the behaviour changed when it fired. The test and everything it calls were byte-identical to the commit where the same job had been green:

git diff <green-commit>..<red-commit> -- tests/test_adagents_ads_redirects.py src/adcp/adagents.py tests/conftest.py
  0 lines

The parametrized value is also excluded: the first hop is identical across all five parameters and only the second route's target differs, so a failure occurring before the first client is created cannot depend on an input that only affects hop two. Four parameters passed in the same run.

Suggested direction, not a prescription

For the redirect test the budget is incidental to the assertion — it checks a redirect policy, not a deadline — so the timing dependency can be removed rather than loosened; raising 1s to a larger number is the same defect with a longer fuse. Worth noting that the two tests which genuinely exercise the deadline (test_missing_location_and_total_timeout_preserve_original_404 and test_total_budget_decreases_across_hops_and_factory_time_counts) use their own factories and do not go through the shared walk() helper, so they keep their coverage however the helper changes.

For test_get_properties_by_agent_cafemedia_scale a wall-clock threshold is the point of the test — its docstring says it is "wall-clock-bounded to catch O(N×M) regressions in the resolver" — so the options differ: a much larger margin, an operation-count assertion instead of a duration, or marking it so it does not run under contention.

Happy to send a patch for either if you have a preference on direction.

Activity

  1. added
    claude-triagingTriage routine is actively working on this issue (1-3 min)
    bugSomething isn't working
    and removed
    claude-triagingTriage routine is actively working on this issue (1-3 min)
    on Oct 6, 2026
  2. bokelley commented on Oct 6, 2026

    @bokelley
    Contributor

    Triage

    Classification: Bug
    Bucket(s): client
    Status: drafting-pr
    Milestone: (omitted — no target version specified)

    What the experts said:

    • code-reviewer: both fixes are correct; no blockers; commented values are self-documenting; production asyncio.TimeoutError → [] swallow is intentional and out of scope
    • dx-expert: both fixes are correct and ship-ready; nit that five other direct timeout=1 calls in test_adagents_ads_redirects.py (not in walk()) carry the same latent exposure; production swallow behavior is tested and correct

    My take: Both failures are intra-worker event-loop starvation under pytest -n 2 --dist=loadfile, not algorithmic bugs. The minimal fix is to raise each budget well above realistic scheduling jitter; explanatory comments prevent future regression back to tight values. Draft PR #1408 implements exactly this — test files only, no production changes.

    Draft PR: #1408


    Triaged by Claude Code. Session: https://claude.ai/code/session_01ChKTrDbAu78k2RuA7mwBxq


    Generated by Claude Code

  3. KonstantinMirin commented on Oct 6, 2026

    @KonstantinMirin
    CollaboratorAuthor

    A third instance, reported independently: test_new_mutations_timeout_with_recovery_metadata[sync_principal] gates on a 0.01 s timeout and fails the same way under -n 8 on unchanged main, with five other failures in the same run passing when re-run alone.

  4. added
    claude-triagingTriage routine is actively working on this issue (1-3 min)
    on Oct 6, 2026
  5. bokelley commented on Oct 6, 2026

    @bokelley
    Contributor

    Triage update — scope expansion

    New instance confirmed: test_new_mutations_timeout_with_recovery_metadata[sync_principal] (0.01 s budget, fails under -n 8) is the same defect class as the two tests originally reported — a wall-clock budget tight enough that event-loop scheduling jitter under pytest-xdist can expire it before the test body does meaningful work.

    What ships with #1408: the two originally-reported tests (test_off_root_destination_must_not_redirect, test_get_properties_by_agent_cafemedia_scale). PR #1408 was updated from Closes to Refs to prevent issue auto-close on merge; the third test has no coverage there.

    What remains:

    • Locate test_new_mutations_timeout_with_recovery_metadata[sync_principal] (likely in tests/test_mutations.py or a nearby file) and raise its 0.01 s wall-clock budget to a value that cannot be consumed by scheduling jitter — same approach as fix(adagents): remove wall-clock sensitivity from two flaky adagents tests #1408. The fix is test-only; no production changes required. Verify with pytest -n 8 <test-file> to confirm the failure disappears, then ruff check / black --check.

    Once the third test is fixed, update the fixing PR to Closes #1407.


    Triaged by Claude Code. Session: https://claude.ai/code/session_01FNzAqWBMMJo9Y7VbNuBpem


    Generated by Claude Code

  6. removed
    claude-triagingTriage routine is actively working on this issue (1-3 min)
    on Oct 6, 2026
  7. bokelley commented on Oct 6, 2026

    @bokelley
    Contributor

    Fixed by #1408 (squash 0d2e61d).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions