Skip to content

fix(e2e): eliminate intermittent Aspire restore cancellation - #1305

Closed
rickylabs wants to merge 12 commits into
mainfrom
fix/aspire-restore-stability-1227
Closed

fix(e2e): eliminate intermittent Aspire restore cancellation#1305
rickylabs wants to merge 12 commits into
mainfrom
fix/aspire-restore-stability-1227

Conversation

@rickylabs

@rickylabs rickylabs commented Aug 5, 2026

Copy link
Copy Markdown
Owner

Summary

Eliminate the intermittent Aspire bundled-NuGet restore failure that halted published Quickstart walks. Preserve the finite retry/classification improvement, retain Aspire CLI diagnostics, and hydrate Aspire's actual project-local integration cache from exact pinned packages before the walk.

Scope

Slices

  • S1 Capture and read Aspire CLI diagnostic logs — 27b0f86ed
  • S2 Add exact-signature retry and a prerequisite pinned package cache — 2bd314ee2
  • S3 Correct the Quickstart response-probe scope — cfce70af7
  • S4 Bound the second restore boundary in database commands — 02d55cefd
  • S5 Hydrate Aspire's project-local integration cache offline — 82d89f4d050fdb28c0
  • S6 Add isolated repeated-proof dispatch and prove three clean runs — 0367dfb95ae71db70a

Diagnosis

Run 30962130571 retained the previously discarded Aspire logs. The failing child log shows BundleNuGetService.RestorePackagesAsync spending the entire 180-second budget in the exact five-package aspire-managed nuget restore, then throwing TaskCanceledException; no container operation had begun. Run 30964226683 found the same defect in the four-package database-operation AppHost. Run 30965320792 proved that a hit in ~/.nuget/packages alone does not satisfy Aspire's project-local TypeScript integration restore.

The workflow now converts the audited global cache into a pinned local NuGet source and uses Aspire's own 13.4.6 aspire-managed binary to hydrate both production-observed project-local cache identities. Hydration disables redundant online audit only after the prerequisite acquisition was audited and has a 30-second hard bound. The classified two-attempt fallback remains restricted to the two observed infrastructure signatures; product failures are single-attempt.

Validation

  • Focused Quickstart/cache/retry/policy tests: 19 passed
  • Targeted deno check --unstable-kv: passed
  • Scoped lint/fmt: passed
  • Workflow YAML parse: passed
  • Local offline cache hydration: 1.68s; subsequent cold-fixture aspire restore: 7.10s
  • Three consecutive clean cloud Quickstart walks on final head ae71db70a:
    • run 30967593436: 7/7 passed, 159.006s total; Aspire step 42.692s
    • run 30967593465: 7/7 passed, 162.117s total; Aspire step 34.295s
    • run 30967593521: 7/7 passed, 133.844s total; Aspire step 31.422s
  • Inherited deno.lock churn remains excluded

Harness

  • Run dir: .llm/runs/fix-aspire-restore-stability-1227--1227/
  • Route: openai / gpt-5.6-sol / medium
  • D6 composed evaluation; no local PLAN-EVAL
  • Phase: implementation evaluation / orchestrator pre-merge gate

Definition of Done

  • The captured Aspire CLI log establishes whether cancellation is feed/package latency, container runtime, or an Aspire CLI defect
  • The exact cancellation signature is retried within a finite budget without retrying product failures
  • Exact pinned Aspire SDK packages restore from a populated cache rather than a cold feed
  • N consecutive published-canary Quickstart walks pass (N=3)
issue: 1227
entries:
  - box-index: 4
    evidence: "Run 30962130571 artifact cli_20260805T001726_084d9e65.log identifies Aspire 13.4.6 BundleNuGetService.RestorePackagesAsync cancellation during the exact five-package restore, before containers; run 30964226683 proves the same four-package database-AppHost path."
  - box-index: 5
    evidence: "2bd314ee2 and 02d55cefd: two attempts only for exit 6 plus both preparation-cancellation markers, or the production exit-2 AppHost-start timeout plus log marker; product failures remain single-attempt."
  - box-index: 6
    evidence: "82d89f4d0 through 50fdb28c0: exact Aspire 13.4.6 packages are acquired/audited once, materialized as a local source, and hydrated by pinned aspire-managed into both observed project-local restore identities with a 30s bound."
  - box-index: 7
    evidence: "Final head ae71db70a: consecutive clean cloud runs 30967593436, 30967593465, and 30967593521 each report ok:true and all seven Quickstart verdicts passed against published 0.0.5-canary.10."

@rickylabs rickylabs added this to the 0.0.5 milestone Aug 5, 2026
@rickylabs rickylabs added area:tooling priority:p0 Critical / release blocker gate:e2e status:research Harness research phase labels Aug 5, 2026
@rickylabs

Copy link
Copy Markdown
Owner Author

Research / diagnostic slice: run 30961102523 referenced an Aspire CLI log at ~/.aspire/logs but artifact 8913213616 retained only suite reports. Commit 27b0f86ed adds always-on CLI-log capture plus a workflow policy regression. The next action is a branch workflow run against canary.10; implementation of retry/cache changes waits on that log.

@rickylabs

Copy link
Copy Markdown
Owner Author

S2 landed in 4e9a42a0b: retained local logs for the identical failure place cancellation in Aspire 13.4.6 BundleNuGetService.RestorePackagesAsync, before containers. Both cloud evidence runs missed cache key v1 and red jobs never saved it. The production workflow now has a prerequisite job that restores, verifies, and saves all five exact SDK packages under v2 before E2E; quickstart retries once only for exit 6 plus both observed cancellation markers. Focused tests: 8 passed; scoped check/lint/fmt, quality scan, architecture gate, YAML parse, and a clean five-package dotnet restore passed.

@rickylabs

Copy link
Copy Markdown
Owner Author

Correction to the preceding S2 comment: the pushed S2 commit is 2bd314ee2 (the scope and validation evidence are unchanged).

@rickylabs

Copy link
Copy Markdown
Owner Author

Proof run 30962998528 was not counted: restore passed in 22.58s from a confirmed 163 MB v2 cache hit, but the walk later failed because step 7 reused the runtime suite’s database-aware health assertion. Commit HEAD makes only the Quickstart call service-scoped; scaffold.runtime still passes the explicit database and retains the stronger check. Targeted tests: 13 passed; targeted check/lint/fmt passed. Consecutive proof restarts from zero.

@rickylabs

Copy link
Copy Markdown
Owner Author

The suite-scope correction referenced above is commit cfce70af7.

@rickylabs

Copy link
Copy Markdown
Owner Author

[PHASE: RESEARCH]

The root-cause slice in #1308 supersedes this PR mitigation while preserving S1 log capture.

Findings

  1. The canceler is NetScript command timeout; Aspire is blocked in BundleNuGetService.RestorePackagesAsync before that signal.
  2. aspire ls leaks orphaned aspire-managed nuget search helpers (macOS) that accumulate over days and deadlock unrelated dotnet restore via NuGet lock contention microsoft/aspire#18948 identifies the exact 13.4.6 stopped NuGet-search helper lock defect; #18958 is merged after stable 13.4.6.
  3. This branch cache preseed did not fix it: run 30964226683 hung after a verified cache, and run 30965320792 made two consecutive preseeded retries that both failed at 180 seconds with exit 6.

Next

@rickylabs

Copy link
Copy Markdown
Owner Author

Superseded by #1308. Root cause is microsoft/aspire#18958 ("Stop leaking orphaned aspire-managed NuGet search helpers"), merged upstream 2026-08-03 into milestone 13.5 — 44 days after our pinned CLI 13.4.6 was published. The restore cancellation is a leaked-process contention failure inside the Aspire CLI, so the retry budget and pinned cache in this PR treat contention as environmental when it was a process leak. Your S1 log capture is retained and reused in #1308 — it is what made the diagnosis possible. Closing rather than merging so we do not carry a mitigation for a defect we can fix by moving to the build that repairs it.

@rickylabs rickylabs closed this Aug 5, 2026
@rickylabs rickylabs added status:impl-eval and removed status:research Harness research phase labels Aug 5, 2026
@rickylabs rickylabs reopened this Aug 5, 2026
@rickylabs
rickylabs marked this pull request as ready for review August 5, 2026 01:56
@rickylabs

Copy link
Copy Markdown
Owner Author

Orchestrator: my close was premature — this stays open, and your sequencing is right.

You wrote "close #1305 in favor of #1308 if the five-run fixed-daily proof passes". I closed it immediately instead. That was wrong: if the five-run proof fails, this branch's controls are the fallback, and closing it first would have thrown away the alternative while the replacement was unproven. Leaving it open until #1308's proof lands.

Two corrections to the record, both from your findings, which are more precise than the summary I circulated:

  1. The canceller is ours, not Aspire's. I reported this as Aspire self-cancelling. Your log read says the NetScript command timeout fires while Aspire is blocked inside BundleNuGetService.RestorePackagesAsync. That materially changes the description: "A task was canceled" is our timeout landing on a restore that is already stuck, not Aspire aborting itself.
  2. Defect vs fix. microsoft/aspire**#18948** is the defect report (aspire ls leaks orphaned aspire-managed nuget search helpers); #18958 is the merged fix. I cited only #18958 as "the root cause", which conflated the two.

And your negative result is load-bearing — please keep it visible in the final write-up: the cache preseed did not help. Run 30964226683 hung after a verified cache, and run 30965320792 made two consecutive preseeded retries that both failed at 180s with exit 6. That independently rules out cold-feed latency and corroborates the helper-lock mechanism, which is stronger evidence than the fixed-daily green run alone.

Condition for closing this: #1308's five consecutive published-canary workflows pass. If they do not, this branch is what we fall back to.

@rickylabs

Copy link
Copy Markdown
Owner Author

Closing now — the condition I recorded is met. #1308 merged and #1227 is CLOSED: the five consecutive published-canary workflows passed at immutable head 5c9a656 (restore/start 18.6–21.2s), so the fixed-daily pin is proven and this branch is no longer the fallback.

Your S1 log capture is what made the diagnosis possible and it lives on in #1308. Thanks for stopping when the mitigation stopped making sense rather than pushing it through — the cache-preseed negative results (run 30964226683 hung after a verified cache; 30965320792 failed two preseeded retries at 180s) were what ruled out cold-feed latency and pointed at the helper-lock mechanism.

@rickylabs rickylabs closed this Aug 5, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

fix(e2e): runtime.aspire-restore intermittently hangs 15min to timeout against NuGet feeds — 3 occurrences in one day, local and cloud

1 participant