Skip to content

ci(#6697): make harness-wait timeouts report why the wait failed - #6698

Merged
waynesun09 merged 1 commit into
mainfrom
agent/6697-harness-wait-timeout
Aug 28, 2026
Merged

ci(#6697): make harness-wait timeouts report why the wait failed#6698
waynesun09 merged 1 commit into
mainfrom
agent/6697-harness-wait-timeout

Conversation

@fullsend-ai-coder

@fullsend-ai-coder fullsend-ai-coder Bot commented Aug 27, 2026

Copy link
Copy Markdown
Contributor

Summary

Makes the harness-wait timeout errors in the E2E behaviour-test GitHub Actions driver report what actually went wrong. Investigating the two #6647 failures that motivated #6697 showed both were misreported by this path rather than caused by the deadline or the artifact lookup, so this PR replaces the first cut (15-minute harnessWait + run-first success fallback) with error surfacing and diagnostics.

Related Issue

Closes #6697

What the #6647 failures actually were

Both from E2E run 33104621218:

  • Attempt 1 (no recent workflow runs found after trigger time): the fullsend.yaml runs existed — created 2s after the label in halfsend-10/test-repo-11 and test-repo-08, both concluded success. The pool-org installation token was rate limited (403 retryable error after 5 attempts ... last delay: 54s in the same job's log from 18:54 onward). listHarnessRunsAfter turned every listing error into an empty list and the artifact branch was if err == nil, so the wait was blind for its whole window and reported that nothing existed. Client-side retries (5 × Retry-After) also stretched the 12-minute wait to ~26 minutes.
  • Attempt 2 (recent workflow runs (1): run 33108146650: status=completed conclusion=success): that run has 0 artifacts and its Harness run (${{ matrix.agent }}) job is skipped — the matrix never expanded. The dispatch job logged collaborator permission lookup failed for fullsend-ai-e2e[bot] on halfsend-11/test-repo-01: not found on a repo recreated minutes earlier, and emitted matrix={"include":[]}. The harness was never dispatched; no wait length or artifact lookup would have found it.

Neither cause is fixed here (see follow-ups below) — but the timeout now names them.

Changes

  • listHarnessRunsAfter returns its error instead of an empty list; both harness waits record artifact/run listing failures per poll (pollErrors) and keep polling — a transient error never ends a scenario.
  • Each poll's API calls are bounded by the remaining wait budget, so client retries cannot overrun dispatchWait. A poll is skipped rather than started with less than pollMinBudget (5s), and a call cut short by the budget is counted separately from API failures — it is never presented as one.
  • Timeout diagnostics (harnessTimeoutDiagnostics, a 2-minute envelope with a 30s lookupBudget per call since the token may still be rate limited; both single-call listings run before the per-run job lookups so neither can be starved; a lookup cut short at diagnostics time — judged by its own context, not the error type — headlines the last poll error instead of its own cutoff):
    • per completed run, the agent job's status/conclusion — or "harness matrix not expanded" when only the unexpanded placeholder job exists, attributed through the Harness dispatch job's own conclusion (placeholder skipped + dispatch succeeded → empty matrix, i.e. dispatch declined the event; dispatch failed → that job's failure; placeholder cancelled → the run ended before the matrix was evaluated, which says nothing about the matrix) (attempt 2's shape);
    • listed artifacts classified against the trigger time actually used (absent / created before trigger / unparseable / eligible-so-miss-was-downstream) instead of asserting a cause;
    • run listing failed: <err> (same error on N of M polls during the wait) when the wait was blind (attempt 1's shape), plus run-lookup (GetWorkflowRun / jobs) failures recorded during the wait.
  • nowFunc seam on Driver (default time.Now) so the timeout branch is unit-testable; dispatchWait is unchanged.
  • Dropped from the first cut: harnessWait = 15m (no latency data supported it; under rate limiting it only extends blind polling) and the run-first success fallback (addressed no observed failure, checked run rather than job conclusion, and added a ListWorkflowRunJobs call per run per poll — more API pressure in exactly the failing condition).

Testing

  • go vet, gofmt clean; go test -race ./pkg/behaviourtest/... passes
  • TestWaitForHarnessAgent_TimeoutReportsListingErrors / TestWaitForFailedHarnessAgent_TimeoutReportsListingErrors — every listing fails (403); timeout names the error and the poll count, never "no recent workflow runs"
  • TestWaitForHarnessAgent_TimeoutReportsUnexpandedMatrix — successful run with skipped placeholder job → "harness matrix not expanded ... dispatch declined the event"
  • TestWaitForHarnessAgent_TimeoutReportsAgentJobAndArtifactRejection — agent job state per run + artifact rejected against the trigger time
  • TestWaitForHarnessAgent_PollsBoundedByRemainingBudget — every poll call carries a deadline within [pollMinBudget, dispatchWait], shrinking per iteration; diagnostics lookups within lookupBudget
  • TestHarnessTimeoutDiagnostics_CutShortVsLiveDeadlineError — a diagnostics lookup cut short by its budget headlines the recorded 403 (or names the cutoff when nothing was recorded); a deadline error under a live context is reported as the real failure it is
  • TestWaitForHarnessAgent_SkipsPollBelowMinimumBudget — a poll that would start with <5s is skipped, not run and reported as cut short
  • TestFormatRunDiagnosticsWithJobs — empty and multi-run headers
  • TestDescribeAgentJob — agent job / unexpanded matrix (dispatch succeeded, failed, absent; placeholder cancelled rather than skipped) / no jobs / lookup error
  • TestPollErrors_KeepsInformativeErrorOverBudgetCutoff (budget cutoff vs a deadline error under a live or merely cancelled context, jitter-insensitive same-error collapse), TestFormatArtifactDiagnostics

Follow-ups (not in this PR)

  • Rate-limit pressure on the pool-org installation token — 12 concurrent scenarios polling one token; the real driver of attempt-1-style flakes.
  • Dispatch silently routing to no-agent when the collaborator permission lookup errors on a freshly recreated pool repo (attempt 2).

Checklist

@fullsend-ai-coder
fullsend-ai-coder Bot requested a review from a team as a code owner August 27, 2026 20:17
@fullsend-ai-coder fullsend-ai-coder Bot added the ready-for-review Triggers review agent dispatch label Aug 27, 2026
@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

🤖 Finished Review · ✅ Success · Started 8:19 PM UTC · Completed 8:35 PM UTC

Commit: 08344ae · View workflow run →

Runtime: claude · Model: opus → claude-opus-4-6 · Effort: high · Cost: $5.12

@codecov

codecov Bot commented Aug 27, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.

📢 Thoughts on this report? Let us know!

@fullsend-ai-review fullsend-ai-review Bot added the risk/moderate PR risk: moderate label Aug 27, 2026
@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

Risk Assessment: moderate (2/5)

Details

Score holds at 2 (moderate). Focused 2-file bug fix with 50% test coverage ratio in a high-churn area (12 commits/30d, 7 fix commits/90d), scoped tightly to harness-wait timeout diagnostics with bot authorship and no protected/security paths touched.

Previous run

Risk Assessment: moderate (2/5)

Details

Focused 2-file bug fix with 50% test coverage ratio in a high-churn area (12 commits/30d, 9 fix commits/90d), but scoped tightly to the harness-wait deadline with bot authorship and no protected/security paths touched.

@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

Review

Findings

Low

  • [return-value ordering] pkg/behaviourtest/drivers/ci/githubactions/githubactions.gowithLookupBudget returns (T, error, bool), placing the error before the boolean. Every other multi-return function in this file places error last (runHasAgentJob, settleHarnessDispatchCount, harnessPollOnce, failedHarnessPollOnce). The inconsistency is contained — unexported helper, 3 call sites, type system prevents misassignment — but reordering to (T, bool, error) would match Go convention and the file's own patterns.

  • [edge-case] pkg/behaviourtest/drivers/ci/githubactions/githubactions.go — In describeAgentJob, the case placeholder.Conclusion != "skipped" branch renders the matrix job concluded %s without expanding. A placeholder job with an empty-string conclusion would produce a doubled space in the message. In practice this is unreachable (the function is only called for completed runs where the placeholder has a non-empty conclusion), so this is purely cosmetic.

Previous run

Review

Findings

Medium

  • [error-handling-gap] pkg/behaviourtest/drivers/ci/githubactions/githubactions.go:631 — In the run-first fallback of WaitForHarnessAgent, the error from runHasAgentJob is silently discarded (hasJob, _, _ := d.runHasAgentJob(...)). When the ListWorkflowRunJobs API call fails, hasJob is false and the run is silently skipped. If the API is consistently failing (e.g., rate-limited), the function will time out after 15 minutes with diagnostics that omit the job-listing errors. By contrast, WaitForFailedHarnessAgent captures this error into lastJobErr and appends it to the timeout diagnostic — a pattern that has proven useful for debugging similar timeout scenarios.
    Suggestion: Track the last runHasAgentJob error (similar to WaitForFailedHarnessAgent's lastJobErr pattern) and include it in the timeout error message. This does not affect success-path behavior, only timeout diagnostics.

fullsend-ai-review[bot]

This comment was marked as outdated.

@fullsend-ai-review fullsend-ai-review Bot added the requires-manual-review Review requires human judgment label Aug 27, 2026
@waynesun09
waynesun09 force-pushed the agent/6697-harness-wait-timeout branch from 08344ae to ffbd823 Compare August 27, 2026 20:39
@waynesun09 waynesun09 changed the title ci(#6697): separate harness-wait deadline and add run-first fallback ci(#6697): make harness-wait timeouts report why the wait failed Aug 27, 2026
@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

🤖 Review · ⚠️ Cancelled · Started 8:41 PM UTC · Ended 8:53 PM UTC

Commit: ffbd823 · View workflow run →

@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

🤖 Review · ⚠️ Cancelled · Started 8:55 PM UTC · Ended 9:04 PM UTC

Commit: 87f9337 · View workflow run →

@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

🤖 Review · ⚠️ Cancelled · Started 9:06 PM UTC · Ended 9:18 PM UTC

Commit: 24a4b34 · View workflow run →

@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

🤖 Review · ⚠️ Cancelled · Started 9:19 PM UTC · Ended 9:24 PM UTC

Commit: a91248a · View workflow run →

@waynesun09
waynesun09 force-pushed the agent/6697-harness-wait-timeout branch 2 times, most recently from a91248a to 4ceb343 Compare August 27, 2026 21:23
@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

🤖 Review · ⚠️ Cancelled · Started 9:26 PM UTC · Ended 9:31 PM UTC

Commit: 4ceb343 · View workflow run →

Investigating the #6647 behaviour-test failures showed both were
misreported by the harness-wait timeout path, not caused by the
deadline or the artifact lookup:

- Attempt 1: the harness runs existed within 2s of the label, but the
  pool-org installation token was rate limited (403) for the rest of
  the wait. listHarnessRunsAfter turned every listing error into an
  empty list, so the timeout said "no recent workflow runs found".
  Client-side retries also stretched the 12-minute wait to 26 minutes.
- Attempt 2: dispatch declined the event (collaborator permission
  lookup failed for the labelling actor on a freshly recreated pool
  repo), the harness matrix never expanded, and no artifact was ever
  uploaded. The timeout showed a "successful" run with no explanation.

Record listing errors during the wait instead of swallowing them, bound
each poll's API calls to the remaining wait budget, and make the timeout
diagnostics state the agent job's state per run (detecting the
unexpanded matrix), classify listed artifacts against the trigger time,
and report the recorded errors. Add a nowFunc seam so the timeout branch
is unit-testable.

The 15-minute harnessWait and run-first fallback from the first cut of
this branch are dropped: neither addressed an observed failure, and the
fallback added an API call per run per poll under rate pressure.

Closes #6697

Assisted-by: Claude (fix), Codex (review), Gemini (review)
Signed-off-by: Wayne Sun <gsun@redhat.com>
@fullsend-ai-review

fullsend-ai-review Bot commented Aug 27, 2026

Copy link
Copy Markdown

🤖 Finished Review · ✅ Success · Started 9:33 PM UTC · Completed 9:50 PM UTC

Commit: 3f4d92f · View workflow run →

Runtime: claude · Model: opus → claude-opus-4-6 · Effort: high · Cost: $5.42

@fullsend-ai-review fullsend-ai-review Bot added ready-for-merge All reviewers approved — ready to merge and removed requires-manual-review Review requires human judgment labels Aug 27, 2026

@waynesun09 waynesun09 left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code-owner approval after five multi-agent review rounds (Claude, Codex, Gemini) plus the review bot's approval at 3f4d92f. Every MEDIUM+ finding was fixed and re-verified: run-vs-job conclusion (moot, code removed), zero-budget final poll, diagnostics-budget cutoff headline, cutoff classification tied to the context's own deadline, placeholder-job attribution through the Harness dispatch job, non-exhaustive cause wording. go test -race -count=5 clean; both real #6647 failure shapes render correctly against the live client source. Diagnostics-only change; dispatchWait and the #6669 backoff untouched.

@waynesun09
waynesun09 added this pull request to the merge queue Aug 27, 2026
Merged via the queue into main with commit 6ca7624 Aug 28, 2026
63 checks passed
@waynesun09
waynesun09 deleted the agent/6697-harness-wait-timeout branch August 28, 2026 00:03
@fullsend-ai-retro

fullsend-ai-retro Bot commented Aug 28, 2026

Copy link
Copy Markdown

🤖 Finished Retro · ✅ Success · Started 12:04 AM UTC · Completed 12:24 AM UTC

Commit: 3f4d92f · View workflow run →

Runtime: claude · Model: opus → claude-opus-4-6 · Effort: high · Cost: $5.42

@fullsend-ai-retro

Copy link
Copy Markdown

Retro: PR #6698 — make harness-wait timeouts report why the wait failed

Timeline

  1. 19:54waynesun09 filed #6697 with two hypothesized root causes for E2E behaviour-test timeout misreports.
  2. 19:56–20:00 — Triage agent (run 33110707633, $0.75) accepted the hypotheses, applied ready-to-code, and proposed test cases for both.
  3. 20:01 — waynesun09 dispatched /fs-code with explicit guardrails: "Both root causes are hypotheses, not confirmed mechanisms — establish which one actually fired before fixing."
  4. 20:03–20:17 — Code agent (run 33111294931, $4.96) produced commit 08344ae — a speculative fix (separate 15-min timeout + run-first success fallback) built on the unverified hypotheses, ignoring the investigation directive.
  5. 20:17–20:35 — First review (run 33112579049, $5.12) found a valid MEDIUM error-handling gap in the run-first fallback.
  6. 20:39 — waynesun09 disproved both hypotheses using pool-repo logs and began a complete rewrite.
  7. 20:39–21:31 — Six force-pushes by waynesun09, triggering five cancelled review runs.
  8. 21:31–21:50 — Final review (run 33118509660, $5.42) approved with only LOW findings.
  9. 23:50 — waynesun09 approved as code owner after five multi-agent review rounds (Claude, Codex, Gemini).
  10. 00:03 — PR merged.

What went well

What could improve

  • The code agent's work was 100% replaced. The agent produced +225/−11 lines that were entirely rewritten by the human (+878/−116 lines). The agent's $4.96 in compute produced zero lines in the merged code.
  • The code agent ignored an explicit investigation directive. The /fs-code command said to "establish which one actually fired before fixing," but the agent jumped to implementing speculative fixes based on unverified hypotheses.
  • The agent added API pressure in the exact failure scenario. The run-first fallback added a ListWorkflowRunJobs call per run per poll — more API calls in conditions where the root cause was API rate limiting.
  • Total cost was ~$16–21 with ~70% waste. Only ~$6 was productive (final review). The code agent, first review (on replaced code), and cancelled reviews were wasted.

Evidence for existing issues

  • agents#299 (verify hypothesis before implementing): Direct evidence — the agent coded speculative fixes for two hypotheses that were both wrong, producing work that was entirely replaced.
  • agents#977 (follow explicit investigation directives): Direct evidence — the /fs-code dispatch explicitly said to investigate first, and the agent ignored this.
  • fullsend#4960 (debounce review runs on rapid force-pushes): Five review runs were cancelled during a 52-minute human rewrite session with ~8–12 minute push intervals.
  • fullsend#2251 (triage should validate hypotheses): The triage agent accepted the issue's hypotheses without validation and applied ready-to-code.

Proposals filed

waynesun09 added a commit that referenced this pull request Sep 1, 2026
The harness-wait poll loop (and its diagnostics) re-request the same
workflow-runs/jobs/artifacts URLs every few seconds, from up to a
dozen concurrent scenarios sharing one installation token. #6705's
instrumentation measured that traffic draining the primary quota
~235 req/min, exhausting it ~20 minutes into a suite run.

GitHub does not count a 304 response against the primary rate-limit
budget (verified against the live API: repeated If-None-Match
requests left X-RateLimit-Remaining unchanged, only the initial
uncached GET consumed one unit). This adds a small conditional-GET
cache to LiveClient (etagCache, opt-in per path via getCached) and
wires it into the five GET endpoints the harness-wait poll loop and
its diagnostics use: ListWorkflowRuns, ListRecentWorkflowRuns,
ListWorkflowRunJobs, ListWorkflowRunArtifacts, and
ListRepositoryArtifacts. Unchanged results between polls now cost
nothing; a status change still forces a full re-fetch, since GitHub
issues a new ETag whenever the underlying data changes.

do() grows a variadic requestHeader option so getConditional can set
If-None-Match without touching its other 28 call sites. The cache is
capped (etagCacheLimit) since a long suite run touches many distinct
run/job/artifact URLs.

Deliberately out of scope: a remaining-budget circuit breaker (the
issue's second candidate). If post-merge behaviour runs still show
#6698's 403 diagnostics after this lands, that's the next step, sized
with real data instead of a guessed threshold.

Assisted-by: Claude
Signed-off-by: Wayne Sun <gsun@redhat.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ready-for-merge All reviewers approved — ready to merge ready-for-review Triggers review agent dispatch risk/moderate PR risk: moderate

Projects

None yet

Development

Successfully merging this pull request may close these issues.

E2E behaviour: harness-agent waits time out at 12 min despite a successful run

1 participant