Repro + analysis: scheduler inconsistent-graph-state on edge-merge + job cancel (draft)

[kmannislands]

Draft — for discussion, not merge-ready

Investigation into the intermittent scheduler failure failed to get edge: inconsistent graph state (and the sibling return leaving outgoing/incoming open) that we see under parallel Earthly builds — tracked internally at EarthBuild/earthbuild#768, upstream at moby/buildkit#4733 / #2303. This PR carries a local repro, one independent race fix, and a production-forensics logging change found along the way. The actual logic fix is left open pending discussion (see below).

Stacked on merge-in-buildkit-all-at-once.

What's here

1. fix(solver): read req under lock in pipe Finalize. sender.Finalize read pw.req.Canceled without pw.mu while receiver.Cancel → setRequest writes it under pw.mu. The request-function goroutine's Finalize races a concurrent Cancel (confirmed by go test -race). Independent of the logic bug below; safe on its own.
2. test(solver): skip-guarded repro of the inconsistent-graph-state failure. Green (skipped) in CI; run with BUILDKIT_TEST_SCHEDULER_MERGE_CANCEL=1.
3. fix(solver): digest-scoped, untruncated log at the error site. The error site dumped the whole ~10k-entry tracker ring (dgstTracker.String(), tens of KB); log ingestion truncates it (~76 KB), dropping the newest-first tail that carries the delete→lookup ordering we need. Replaced with a discrete structured line (edge_vertex_name/digest/index + desired_state + a bounded, digest-scoped history), and added a mutex to dgstTracker (its String()/add() previously raced). Intended to ship next release so the next production occurrence is definitively fingerprintable.

The repro

Two jobs build distinct vertices that share cache-key seeds, so their edges must edge-merge. A shared cache-map barrier forces their key computation to overlap (so the merge races job teardown). One job is cancelled at the merge point, with Discard deferred to run after Build returns — matching llbsolver.Solve's defer j.Discard(). Reproduces in ~2 of 3 runs within the iteration budget.

BUILDKIT_TEST_SCHEDULER_MERGE_CANCEL=1 go test -run TestSchedulerMergeCancelInconsistentGraphState ./solver/ -count=1

With commit 3 in place, the failing occurrence now logs (compact, digest-scoped):

level=error msg="failed to get edge: inconsistent graph state"
  edge_vertex_name=dep-A edge_vertex_digest=sha256:e11d… edge_index=0 desired_state=complete
  digest_history="get-edge-not-found …; delete …; loadUnlocked-add …; … (+N older)"

i.e. the delete of the failing digest sits immediately before its get-edge-not-found — the exact ordering the truncated dump used to lose.

Root cause (what the event trace shows)

MERGE dep-A -> dep-B ; ADDJOBS dep-B from dep-A      # dep edges merge, refcount propagated OK
DISCARD job=A from=dep-A  -> DELETE dep-A            # A's Discard deletes its states from `actives`
DISCARD job=A from=root-A -> DELETE root-A
MERGE src=root-B -> dest=root-A                      # <- scheduler merges INTO root-A *after* it was deleted

The scheduler performs an edge merge whose destination edge's state has already been removed from actives by a concurrent Job.Discard. The edge survives in edgeIndex because edge.release() only calls index.Release once releaserCount reaches 0 (solver/edge.go), so edgeIndex.LoadOrStore can hand back a merge target whose state is gone. The merged edge then requests a deleted dependency → getEdge()==nil → the error.

This is the same "merge to inactive state" class that #4887 addressed, still reachable in the parallel-cancel window — i.e. #4887 looks incomplete for #4733.

Candidate fix directions (want maintainer input)

The correct fix is non-obvious and is why this is a draft:

• Re-check that the merge destination is still active immediately before mergeTo — but there's a TOCTOU unless the check + mergeTo + setEdge are atomic under Solver.mu (dispatch currently holds only scheduler.mu and takes Solver.mu per-call).
• Or clean the edgeIndex entry when a state leaves actives, independent of releaserCount.
• Or have Job.Discard coordinate with the scheduler so an edge is drained before its state is deleted.

Each has lock-ordering implications we'd rather discuss than guess at.

Field evidence so far (o8t CI, ~15-day window)

Supportive but not yet corroborating:

• Preconditions fit: 6/6 failures on shared multi-tenant daemons running cross-repo targets; 4/6 with a same-second cancellation; one direct rpc … evaluating released result co-occurring in the same second as a failure (a released result being evaluated — the shape this mechanism predicts).
• Fingerprint unconfirmed: the deployed rev logs the truncating ring dump, so the delete→request-same-digest ordering could not be read cleanly. Commit 3 is what unblocks this on the next occurrence.
• Bug has recurred at o8t for ≥13 months (survived one abandoned fix attempt), consistent with a rare timing race.

Notes from the wider investigation (context, not in this PR)

• An initial hypothesis — that addJobs under-propagates job refs (its log-and-continue on not-found) — was falsified: the miss counter stayed 0 across every repro. The bug is merge-to-deleted-state, not ref undercount.
• Running this scenario under -race also surfaces data races originating solely in the fork's helpMe scheduler instrumentation (fmt.Sprintf("%+v", e) racing edge.release()). Removing that block eliminates them; handled separately as part of dropping that instrumentation.

Status / confidence

• Proven: this race exists and produces the exact error on the merge branch; the pipe fix is a real, independent race fix.
• Not yet proven: that this is the cause of every production incident. Commit 3 + a couple more occurrences (or an unskipped deterministic testing/synctest version of the repro) would close that gap.

[github-actions]

⚠️ Are we earthbuild yet?

Warning: "earthly" occurrences have increased by 29 (13.36%)

📈 Overall Progress

Branch	Total Count
main	217
This PR	246
Difference	+29 (13.36%)

📁 Changes by file type:

File Type	Change
Go files (.go)	❌ +26
Documentation (.md)	➖ No change
Earthfiles	➖ No change

---

Keep up the great work migrating from Earthly to Earthbuild! 🚀

💡 Tips for finding more occurrences

Run locally to see detailed breakdown:

./.github/scripts/count-earthly.sh

Note that the goal is not to reach 0.
There is anticipated to be at least some occurences of earthly in the source code due to backwards compatibility with config files and language constructs.

[kmannislands]

Possible to unstack this from the big buildkitd upgrade. Might be a good idea actually so we can collect more field diagnostics from the added debug logs in v0.8.19 prior to the major upgrade release.

[janishorsts]

Use sync.RWMutex for more granular access.

[janishorsts]

Suggested change

	pw.mu.Lock()
	reqCanceled := pw.req.Canceled
	pw.mu.Unlock()
	pw.mu.RLock()
	reqCanceled := pw.req.Canceled
	pw.mu.RUnlock()

[janishorsts]

If it is concurrently as stipulated and implemented before, then this assignment is thread-unsafe.

[janishorsts]

Suggested change

	ctxA, cancelA := context.WithCancel(context.Background())
	ctxB, cancelB := context.WithTimeout(context.Background(), 5*time.Second)
	ctxA, cancelA := context.WithCancel(t.Context())
	ctxB, cancelB := context.WithTimeout(t.Context(), 5*time.Second)