Flake: ActivityLiveProgressTest.EveryProgressLine_LandsWhileTheCommandIsStillRunning — the activity node's owner ends its streams ~5 s in, the next progress write gets no verdict (OwnerUnreachable after 31 s) #2776

Activity

1. rbuergi commented on Aug 30, 2026

   

   rbuergi

   on Aug 30, 2026

   ContributorAuthor

   More actions

   Mechanism identified: this is #2778, and the evidence here is now folded into that issue.

   The trail in the table above — owner's streams end, ADVANCE_WITHOUT_HANDOFF at 5 s, then VERDICT_TIMEOUT at 31 s with OwnerUnreachable — is precisely #2778's hole: RegisterOwnerDisposingNack delivers the transient NACK only while parent.RunLevel < DisposeHostedHubs, so a write in flight when the parent starts disposing hosted hubs gets silence instead of a NACK and the caller waits out its whole budget. That answers this issue's open question 2 ("why does the caller not learn it earlier?") — the 26 seconds between the cache knowing and the caller learning is the dropped NACK.

   Open question 1 — what ended the activity node's streams at +5 s while the activity was still running — is NOT answered by #2778 and is the reason to keep this issue open. #2778 explains why the caller suffered for 26 s; it does not explain why the owner went away mid-run.

   Two sibling occurrences recorded on #2778 for whoever picks up the fix: Plugins' StreamingCellWriteByteCountTest (a PatchDataRequest, ~13 distinct stream ids in one burst) and, on production, every MCP point read answering "reached no verdict within 10s" for ~15 minutes right after a self-update roll, while search and writes stayed healthy.
2. rbuergi commented on Aug 30, 2026

   

   rbuergi

   on Aug 30, 2026

   ContributorAuthor

   More actions

   Correction to my earlier comment here: #2778 is NOT fixed, and #2808 no longer carries its fix.

   I wrote that #2808 closes #2778 and that this issue's mechanism would go with it. The fix has since been reverted out of #2808 (a1cbcee61) because it was the cause of a measured 6× slowdown in MeshWeaver.Content.Test — 29 s on main, 176 s with it, 21 s with it reverted, same box, one variable at a time.

   The reason it was reverted is worth knowing here, because it changes what a fix for this issue has to do: the guard that skipped the teardown NACK once the parent was past DisposeHostedHubs had a wrong stated reason ("nobody is waiting" — this issue is one of the proofs that somebody is) but was load-bearing for an unwritten one: it bounds the work teardown does. Posting a NACK through a live ancestor wakes callers mid-drain, so every hub going down with a delivery outstanding pays. The first attempt traded a rare 31 s hang for a cost every teardown pays.

   So this issue stays open, #2778 stays open, and the mechanism described above still explains the 26 seconds between ADVANCE_WITHOUT_HANDOFF at +5 s and VERDICT_TIMEOUT at +31 s. What has changed is that the obvious fix is known to be too expensive, and a working one has to deliver the NACK without making every teardown pay for it.

   Unchanged: this issue's own open question — what ended the activity node's streams at +5 s while the activity was still running — is not answered by #2778 either way.
3. rbuergi commented on Aug 30, 2026

   

   rbuergi

   on Aug 30, 2026

   ContributorAuthor

   More actions

   Open question 2 is answered, and the answer is "by design" — so the RCA is entirely question 1

   Why does the caller not learn it earlier? ADVANCE_WITHOUT_HANDOFF fires at 5 s, the verdict timeout at 31 s — 26 s of a write that the cache already knew had no acknowledged owner.

   The 5 s bound and the caller's terminal are deliberately independent, and closing the gap would be a regression. From MeshNodeStreamCache at the advance site:

   // 🚨 Advance the per-path queue on the HAND-OFF, or on QueueAdvanceBound.
   // … QueueAdvanceBound remains the backstop for an owner that never answers at all:
   // there the successor genuinely cannot know, and falling back to the mirror is the
   // old behaviour — no worse, and loud.
   // The caller's terminal stays exactly as prompt as before; only the next queued write waits.
   

   ADVANCE_WITHOUT_HANDOFF means "stop blocking the queue", not "this write failed". And the caller must not be failed at 5 s, because silence is the one NACK class that is never retried — MeshNodeStreamExtensions states why: "NEVER retried: silence (a busy owner still applies the original patch)". A busy owner that answers at 20 s still commits. Failing the caller at 5 s would abandon writes that are about to land, which is strictly worse than waiting.

   So there is no 26-second defect. The whole RCA is question 1: what ended the activity node's streams at +5 s.

   A lead for question 1, with the discriminator that would confirm it

   Two things line up, and I want to be explicit that this is a lead rather than a finding — grouping by symptom has cost this repo twice today.

   1. +5 s is the hosted-hub drain cap. LateResponseWatchBound's own comment enumerates what it must dominate: "the disposal NACK after the owner's phased teardown (hosted-hub drain capped at 5 s)". The streams ending at 13:28:32.9 — 5.1 s after TEST START at 13:28:27.8 — is that number, not a coincidence-sized one.

   2. The caller got OwnerUnreachable, not OwnerDisposing. If the owner had been disposing and its NACK had been delivered, the caller would have seen MeshNodeErrorCode.OwnerDisposing at ~5 s — which is one of the three provably-safe retried cases (MaxOwnerDisposingReenqueues = 2), so the write would have been re-enqueued against fresh state and very likely succeeded. Instead it fell through to silence and OwnerUnreachable at the write verdict bound.

   That is exactly the defect #2778 describes: "OwnerDisposing NACK is dropped exactly when the parent is disposing hosted hubs." If it holds here, #2778 does not merely lose a diagnostic — it converts a recoverable, retried OwnerDisposing into 26 s of silence and then an unrecoverable failure, which is precisely this test's shape.

   What is measured: the +5 s stream end, the OwnerUnreachable terminal, the absence of any OwnerDisposing NACK in the trail.
   What is not measured: that the parent was in DisposeHostedHubs at 13:28:32. The log line (no synchronization hub found on this hub or any parent — the target stream is gone) is consistent with it but does not say it.

   The discriminator: a DisposeHostedHubs / phased-teardown entry for the activity's parent hub in that window. If present, #2776 and #2778 are one defect seen from two ends and should be fixed once. If absent, something else ends those streams — recycle (#2763/#2582) or the bounded-message-list flush — and the two stay separate.

   🚨 Relevant to whoever picks this up: #2778's fix was reverted after it produced a ~10× teardown regression (main 29 s / branch 176 s, isolated one variable at a time). The guard's stated reason was wrong but it was load-bearing for bounding teardown work — see Doc/Architecture/GuardsAndUnknownStates. So the NACK still needs delivering, by a route that does not restore that cost.

   Finally: the bound=31s in this trace is LatePatchResponseRegistry.WriteVerdictBound, which #2829 makes public precisely so it stops being re-authored as a literal elsewhere.
4. rbuergi commented on Aug 30, 2026

   

   rbuergi

   on Aug 30, 2026

   ContributorAuthor

   More actions

   A second witness, in another repo — same fingerprint, and it rules out "the bound was too short"

   MeshWeaver.InstanceSync.Test.InstanceSyncRemoteDeletionTest.A_locally_excluded_node_is_never_deleted_for_being_absent_remotely failed on MeshWeaver.Plugins#993 (job 99310456531, 2026-08-30 19:53Z) on a cref-only diff — three <see cref> disambiguations that cannot reach InstanceSync.

   Put the two timelines side by side:

   	#2776 (ActivityLiveProgressTest, core)	new (InstanceSyncRemoteDeletionTest, Plugins)
   TEST START	13:28:27.815	19:53:46.424
   Dropping StreamEndedEvent … no synchronization hub found	13:28:32.936 (+5.1 s)	19:53:51.608 (+5.2 s)
   a second dropped StreamEndedEvent	13:28:32.946	19:53:51.662
   ADVANCE_WITHOUT_HANDOFF … seq=3 bound=5000ms	13:28:32.940	19:53:51.710
   terminal	13:28:58.951 VERDICT_TIMEOUT → OwnerUnreachable	19:54:16.760 TimeoutException [30 s]

   Two dropped sync streams at +5 s, ADVANCE_WITHOUT_HANDOFF at seq=3 within 100 ms, then silence to the caller's bound. Two suites, two repos, one signature. Per this repo's own rule, two tests with one cause is one proof, not two flakes — and it makes the "+5 s is the hosted-hub drain cap" reading much harder to dismiss as coincidence, since the same offset reproduces on unrelated code.

   Why this witness is more informative than the first

   The InstanceSync case fails inside a polling helper:

   protected async Task WaitForNodeGone(string path, TimeSpan? timeout = null) =>
       await Observable.Interval(100.Milliseconds()).StartWith(0L)
           .SelectMany(_ => ReadNode(path))
           .Where(n => n is null)
           .FirstAsync()
           .Timeout(timeout ?? 30.Seconds())
           .Await();

   ~300 read attempts over 30 s, and not one of them returned null. That is the discriminator #2776 could not supply: after the streams are dropped at +5 s, ReadNode stops emitting at all — SelectMany produces nothing, so .Where(n => n is null) can never fire, and the wait must run to its bound whatever that bound is.

   🚨 So this is not #2700. "It failed at exactly its bound" and "its bound was too short" are different facts, and the discriminator is whether the source is still producing. Here it demonstrably is not: a 60 s bound would fail at 60 s. Anyone triaging this by widening the timeout will make it slower and no less red.

   Also in this trace, and worth a look

   At +0.2 s, twice: RouteMessage: NotFound for RawJson → rdel6/doomed. That is a point read of a node that is supposed to become absent — the shape AGENTS.md calls a framework defect, because the owner's routing NotFound terminates the stream and opens the storm-breaker on that path. Whether it contributes here or is merely the expected answer to "is it gone yet" I have not established, and I am flagging it as unexamined rather than folding it into the conclusion. But a helper whose whole job is to wait for non-existence, built on a repeated point read, is worth a second look independently of this failure — the sanctioned shape for existence is a scope:children listing.

   Unchanged

   The leading cause remains #2778 (the OwnerDisposing NACK dropped exactly when the parent is disposing hosted hubs): had it been delivered, the caller would have learned at ~5 s with a code that is retried (MaxOwnerDisposingReenqueues = 2) instead of falling through to silence. And #2778's fix is still reverted for the ~10× teardown regression, so it needs a route that does not restore that cost.
5. rbuergi commented on Sep 1, 2026

   

   rbuergi

   on Sep 1, 2026

   ContributorAuthor

   More actions

   Open question 1 answered, by measurement — and the "~5 s" in this issue's title is an artifact of the diagnostic, not a fact about the run

   Nothing recycled, nothing tore down, and the streams did not end at +5 s. They ended at +0.12 s, and they were ended by the activity's own preceding progress write.

   The two arithmetic corrections

   1. The drop line is written five seconds after the event it describes. DataExtensions.RouteStreamMessage does not drop a StreamMessage whose sync/{id} sub-hub is missing — it holds it for SyncStreamOptions.SyncHubRegistrationGrace (5 s, present at 2abb6a60) waiting for the sub-hub to register, and only logs Dropping … the target stream is gone when that Timeout fires. So a line at T describes an arrival at T − 5 s.

   Re-reading the same trace with that in hand, everything lands in one 10 ms window at +0.12 s, not +5 s:

   log line	logged at	actual event
   Dropping StreamEndedEvent … uZzjE4MWi0KBrSXTSLNN9g	13:28:32.936	arrived 13:28:27.936 (+121 ms)
   ADVANCE_WITHOUT_HANDOFF seq=3 bound=5000ms	13:28:32.940	write started 13:28:27.940 (+125 ms)
   Dropping StreamEndedEvent … dPb18nIfvUCsJEhA8RgoLQ	13:28:32.946	arrived 13:28:27.946 (+131 ms)

   Independently confirmed by the failure's own arithmetic: [UpdateQueue] FAILED … seq=3 elapsedMs=31015.7 at 13:28:58.952 puts req.EnteredAt at 13:28:27.936.

   Two unrelated five-second bounds (SyncHubRegistrationGrace and QueueAdvanceBound), both counting from the same instant, produced a coincidence that looked like a mechanism — and "+5 s is the hosted-hub drain cap" was that coincidence. The second witness (InstanceSyncRemoteDeletionTest, +5.1/+5.2 s) is the same artifact, not a corroboration.

   2. The sender says it was NOT a recycle. There are two emitters of StreamEndedEvent:

   • the recycle announcement (Workspace.AnnounceRecycleToClientSubscriptions) is deliberately posted by a carrier — the parent hub or its spokesman — because a dying hub must never speak for itself;
   • the healthy-owner announcement (JsonSynchronizationStream's disposal registration) is posted by the owner and refuses to fire at all once RunLevel > Started or IsDisposing.

   Both trace lines name GhLive22d6da4e6/_Activity/b55c9a35 — the activity node itself — as sender. That is provably the healthy-owner path, i.e. at that instant the owner was Started and not disposing. #2763/#2582 (recycle) and the hosted-hub drain cap are both eliminated by the trace, not by argument.

   What actually ended them

   IMeshChangeFeed is published by the persistence layer after every create/update/delete. Workspace.EvictForPath listened to it and dropped every cached remote stream whose owner matched the changed path — including the mirror the writer itself was using, on the writer's own write. A cross-hub write leases that mirror only for the duration of its Observable.Create subscription, so:

   1. write N takes a lease on the mirror for P, posts its patch, the owner commits, persistence publishes Updated for P;
   2. EvictForPath("P") removes that very mirror from _remoteStreamCache;
   3. write N settles and releases its lease;
   4. the evicted stream now has no declared holder → ReclaimIfUnheld disposes it → UnsubscribeRequest to the owner → the client sync/{id} hub and its owner-side twin both die;
   5. the owner announces StreamEndedEvent to a subscriber whose sync hub step 4 has just destroyed → held 5 s → dropped with the diagnostic.

   So the answer to "what ended the activity node's streams while it was still running" is: its own previous progress line did. One full subscribe / initial-state / unsubscribe round trip per write, for as long as anything is watching the node.

   Reproduced deterministically in core, and load-independently

   test/MeshWeaver.Graph.Test on the monolith harness — one activity node, one live reader, six progress writes. Counts, not timings, because this box was at load average 100–220 on 18 cores and both bounds in the original trace are ones a starved machine trips on its own:

   	before	after
   client-side sync/ hubs minted	7	2
   owner-side sync/ hubs minted	11	6
   mirror evictions on the change feed	7	0
   mirrors disposed mid-run (⇒ UnsubscribeRequest + StreamEndedEvent)	5	0
   reader emissions (versions 1…7)	7	7

   The regression guard counts owner-side sync/ hubs minted while the writes run, for two write counts. RED before: 2 writes → 4, 8 writes → 16 (exactly two per write). GREEN after: 2 writes → 2, 8 writes → 2.

   The fix

   EvictForPath now probes StreamLiveness.IsUsable and leaves a live mirror alone; a dead one is evicted exactly as before. This is the rule the other two listeners on this same broadcast already state:

   • MeshNodeStreamCache.ResetFailureState: "A healthy live entry is left untouched: the owner's sync stream already delivers routine updates, and tearing the shared handle down on every post-commit broadcast would sever live GUI subscribers."
   • JsonSynchronizationStream's change-feed Resubscribe — coalesced and version-gated after exactly this defect one layer over (ChangeFeedResubscribeCoalesceTest): "a HEALTHY subscriber receives that same write through its own subscription, so resubscribing on it is pure churn — at scale it is the storm that starved prod's hubs."

   EvictForPath was the third listener and the only one still acting unconditionally. Nothing is lost: GetExternalClientSynchronizationStream already re-checks StreamLiveness.IsUsable on every cache hit and rebuilds on a false verdict, and recycled-owner recovery belongs to the stream's own resubscribe ("the sole recycled-grain detector"), the recycle re-arm, and the heartbeat — never to this eviction.

   What this does not claim

   This issue's visible failure was a write that reached no verdict in 31 s. That silence has its own, already-fixed cause — #2882 / #2890 (the write registered its response subject after posting, so a warm owner's sub-millisecond ack could land before anything was listening; the trail could only ever say REGISTERED_AFTER_POST, which is exactly what this trace says). The diagnosability improvement suggested here — switching to the full-trail Observe(request, options) — landed on 2026-08-31 in 4d231170a, the day after this measurement, so the next occurrence will name its own edge.

   So the two halves of this issue have two different causes and both are now addressed: the stream-ending is fixed here, the silence was fixed by #2890. Removing the churn also removes a per-write subscribe/unsubscribe race from the write path, but that is a consequence, not a claim that it caused that particular timeout.

   Full write-up committed as Doc/Architecture/LiveMirrorsAndTheChangeFeed.
6. rbuergi

   added 2 commits that reference this issue on Sep 1, 2026

   docs(#2776): what ends an activity's streams mid-run — and why the ob…

   ...

   f755a05

   test(#2776): seal the awaits with .Await(), and assert instead of sup…

   ...

   42fc87f
7. rbuergi

   closed this as completedin #3013on Sep 1, 2026
8. rbuergi

   added a commit that references this issue on Sep 1, 2026

   Merge pull request #3013 from Systemorph/fix/2776-activity-streams-en…

   ...

   72ea6ae