Skip to content

Flake: OrleansGrainTeardownStragglerTest — the activation never leaves the silo catalog (4 hits on 2026-08-25, all unrelated diffs) #2301

Description

@rbuergi

MeshWeaver.Hosting.Orleans.Test.OrleansGrainTeardownStragglerTest.GrainLifetimeCallbacks_AfterActivationIsInvalid_AreGracefulNoOps_NotThrows
has no issue of its own (only the umbrella #1384). It is currently one of the most frequent members
of the population, and it is accelerating.

Occurrences — four, all on diffs that cannot reach Orleans grain teardown

From a sweep of the last 300 MeshWeaver Build and Test runs, reading [FAIL] lines out of every
attempt
(a re-run-to-green hides the attempt that failed):

run when branch
32841922930 2026-08-25 11:21 —
32883602310 2026-08-25 18:24 —
32886635560 2026-08-25 18:55 —
32905773749 2026-08-25 23:09 fix/2281-listen-readiness-signal (a PostgreSQL LISTEN readiness signal — it cannot reach a grain catalog)

All four on 2026-08-25, all attempt 1. That is a rate worth a name of its own.

What the failure says

System.TimeoutException : The operation has timed out.
  at OrleansGrainTeardownStragglerTest.GrainLifetimeCallbacks_AfterActivationIsInvalid_AreGracefulNoOps_NotThrows()
     OrleansGrainTeardownStragglerTest.cs(98)

Line 98 is the .Timeout(30s) on step 4 — "wait for the activation to leave the silo catalog":

deactivate!.Invoke();
await hub.DisposalCompleted…;               // this part completed — the log line after it prints
…
await Observable.Interval(100ms).StartWith(0L)
    .SelectMany(_ => mgmt.GetDetailedGrainStatistics().ToObservable())
    .Where(stats => stats.All(s => !string.Equals(s.GrainId.ToString(), grainId, …)))
    .FirstAsync()
    .Timeout(TimeSpan.FromSeconds(30))       // ← line 98

So the hub disposed, and then the activation never disappeared from the catalog for a full 30 s.
The test has not even reached the stragglers it exists to exercise; it is stuck waiting for
ActivationData.FinishDeactivating to set State=Invalid.

Leading hypothesis, from something established elsewhere tonight

#2252's author found that routing a message to a deactivating Orleans grain RE-ACTIVATES it. An
activation that is re-created while deactivating never leaves the catalog, which is exactly the state
this wait cannot exit. Anything still addressed at messagehub/{threadPath} in that window —
a lingering stream subscription from the client built in step 1/2, a child hub's parting message, a
heartbeat — would produce it, and would do so load-dependently, which fits a flake that only shows
on a busy runner.

Worth checking before anything else, because if it holds the fix is not in this test.

🚨 And note what must not happen here: the bound is the detector. Raising the 30 s does not make
a re-activated grain leave the catalog; it only makes the test take longer to say so.

Found while working the flake population (#1384). Not fixing it here — my change set is elsewhere.

🤖 Generated with Claude Code

Activity

  1. rbuergi commented on Aug 26, 2026

    @rbuergi
    ContributorAuthor

    Note for whoever picks this up: PR #2270 ("A deactivating silo asks Orleans for no new activation (#2252 class fix)") landed a closely-related fix — it gates OrleansRoutingService's grain calls so a shutting-down silo never asks Orleans for a new activation (the goodbye-announcement and pod-hub-claim call sites). It's CI-green and mergeable but not yet merged as of now.

    It explicitly does not fix this issue, per its own author's note: "This gate keys on the host stopping. OrleansGrainTeardownStragglerTest runs against a healthy cluster, where IsHostStopping is false and this change is a no-op — so it cannot be the fix for #2301... Please do not close #2301 against this PR."

    So the hypothesis in this issue's body (routing a message to a deactivating — not shutting-down-host — grain re-activates it, keeping it in the catalog) is still unconfirmed and still open. Leaving open; flagging #2270 only so it isn't mistaken for the fix once it merges.

  2. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Recurrence AFTER the #2270 fix

    Same test, same line, same symptom — on a branch that provably contains the fix that closed this.

    [07:08:46.034] warn … Grain TestUser/_Thread/teardown-straggler-5b4db2-300d: out-of-band deactivation requ…
    Hub disposal completed — waiting for the activation to leave the catalog...
    [07:09:16.169] === TEST FAILED: The operation has timed out.
    

    30 s between "waiting for the activation to leave the catalog" and the timeout — line 98's
    .Timeout(30s), the same step, with the disposal half already completed.

    The fix is in the tree under test. #2270's merge commit 117b55de3 is an ancestor of the branch
    (git merge-base --is-ancestor — checked, not assumed), so this is not a stale branch re-sampling a
    flake main had already fixed.

    And the diff cannot reach it, on two independent structural grounds — #2476 touches only test
    harness code for #2423:

    • zero files under test/MeshWeaver.Hosting.Orleans.Test/;
    • that project has no reference to MeshWeaver.Hosting.Monolith.TestBase (the one src/ file the
      PR changes), and OrleansGrainTeardownStragglerTest : OrleansSharedTestBase : TestBase never
      passes through it.

    The runner was starved in the same window

    Worth recording because this issue's leading hypothesis is explicitly load-dependent:

    [07:08:57.082] warn … AsyncTimer.LocalSiloHealthMonitor: Timer should have fired at 07:08:53 but fired at 07:08:57
    [07:09:06.616] warn … AsyncTimer.IncomingRequestMonitor:  Timer should have fired at 07:09:03 but fired at 07:09:06
    [07:09:07.092] warn … LocalSiloHealthMonitor: .NET Thread Pool is exhibiting delays of 1.1911617s
    [07:09:07.092] warn … LocalSiloHealthMonitor: Self-monitoring determined that local health is degraded
    [07:09:12.304] warn … Watchdog: .NET Runtime Platform stalled for 00:00:02.0157931
    

    So the re-activation window this issue hypothesises would have been wide open. If #2270 narrowed the
    race rather than closing it, this is what that looks like — and the "only shows on a busy runner"
    note in the original write-up still holds.

    🤖 Generated with Claude Code

  3. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Recurrence — third since the #2270 fix, ~1 h after the last one

    Same test, same line, same symptom. This is the occurrence immediately after the one recorded above
    (PR #2476, 07:09 UTC); it is now firing on consecutive PRs.

    • Run 33052558520, shard 3,
      attempt 1, 2026-08-27 08:16 UTC (PR Recursive delete issues both fan-outs off the router (#2477) #2484, commit a06ad982).
    • MeshWeaver.Hosting.Orleans.Test Total: 223, Errors: 0, Failed: 1 — the one failure being
      OrleansGrainTeardownStragglerTest.GrainLifetimeCallbacks_AfterActivationIsInvalid_AreGracefulNoOps_NotThrows.
    • Log stops at exactly the wait this issue names, and the 30 s gap is line 98's .Timeout(30s):
    [08:15:42.595] warn … Grain TestUser/_Thread/teardown-straggler-8e13fe-8d97: out-of-band deactivation requested…
    Hub disposal completed — waiting for the activation to leave the catalog...
    [08:16:13.577] === TEST FAILED: The operation has timed out.
    
    System.TimeoutException : The operation has timed out.
      at OrleansGrainTeardownStragglerTest.GrainLifetimeCallbacks_AfterActivationIsInvalid_AreGracefulNoOps_NotThrows()
         OrleansGrainTeardownStragglerTest.cs(98)
    

    The disposal half completed (its log line prints); the activation then never left the catalog for a
    full 30 s, so the test never reached the stragglers it exists to exercise.

    The diff cannot reach it — structurally, not by "it's only X"

    PR #2484 (#2477) changes exactly one src/ file, and within it only
    MeshExtensions.HandleDeleteNodeRequest plus four private static helpers it calls
    (PreValidateDescendantsObs, DeleteSubtreeUntilDrained, RunDeletePass, FanOutDeleteSubtree).
    Every one of them executes only under a DeleteNodeRequest delivery.

    test/MeshWeaver.Hosting.Orleans.Test contains zero occurrences of DeleteNodeRequest,
    DeleteNode(, .Delete( or Recursive — the whole project never issues a delete, so none of the
    changed code can run in it. The failing test creates a thread node, reads it, deactivates the grain
    and waits on the Orleans catalog; the fixture's own teardown (CleanupSiloHubsWithPrefix) disposes
    hubs by reflection rather than deleting nodes. No public surface changed either — CI's
    Public surface (binary compatibility) check is green on this commit.

    Both other shards that had completed at that point (0 and 2) were green, and the branch is based on
    6600d35e5, which is downstream of #2270.

    🤖 Generated with Claude Code

  4. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Reopened — three recurrences since #2270, two of them within one hour

    Closed 2026-08-26 12:55:28Z by #2270 ("A deactivating silo asks Orleans for no new activation"). The identical failure has since occurred on at least three PRs whose branches contain that fix:

    PR what it changes verified contains #2270
    #2476 test-harness request origin ✅ git merge-base --is-ancestor
    #2484 recursive-delete fan-out hub ✅
    (a third, ~1 h apart from #2476) — ✅

    Same assertion each time: GrainLifetimeCallbacks_AfterActivationIsInvalid_AreGracefulNoOps_NotThrows, TimeoutException at line 98 — the 30 s wait for the activation to leave the silo catalog.

    Attribution is structural, not statistical

    #2484's diff is HandleDeleteNodeRequest plus four private static helpers, all reachable only under a DeleteNodeRequest delivery. test/MeshWeaver.Hosting.Orleans.Test contains zero occurrences of DeleteNodeRequest, DeleteNode(, .Delete( or Recursive; its fixture disposes hubs by reflection rather than deleting nodes. Public surface (binary compatibility) was green, so no API moved either. The changed lines cannot execute in that project.

    Why this is worth reopening rather than filing anew

    #2270 addressed a real mechanism and the symptom outlived it. Keeping the issue closed makes the next occurrence look like a new flake and invites a fourth fix for the same failure — which is precisely the pattern #2346 exists to stop (per-test issues filed one at a time while one cause sat underneath). The honest state is "fix landed, symptom persists", and that is more useful to whoever picks this up than a closed issue plus scattered comments.

    Blast radius right now

    Together with #2346, this is the fleet's binding constraint: four finished PRs — #2470, #2475, #2438, #2484 — are green except for Orleans teardown/activation failures their diffs cannot reach. Two of them (#2470, #2475) are themselves fixes to CI's ability to report truthfully.

    🚨 Not re-run, deliberately. A re-run to green would hide the race and is what AGENTS.md forbids; its only sanctioned exceptions are a harness crash or a user-killed run, and this is neither. The unblock is a fix, not a retry.

    Possible connection worth testing

    #2346's newest member fails with [took 20s] against three 30s waits — it did not time out; it reached its assertion and found a cell at terminal Completed still holding the placeholder. This test, by contrast, fails on a 30 s timeout. If one cause explains both, it has to explain a state that is simultaneously reached and not settled — which points at completion bookkeeping rather than at scheduler contention. Offered as a discriminator, not a conclusion.

  5. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Cross-posting from #2346 for whoever is on this one — three things that should narrow your search, and one member I am claiming so you don't spend budget on it.

    The #2346 member you may have seen fail instead is MINE, with a mechanism

    If a run of the Orleans suite hands you OrleansNodeChangePropagationTest.Delegation_NodeChanges_PropagateFromSubThread (a delegate_to entry with no DelegationPath) rather than this test: that stamp is written at ThreadExecution.cs:1836 and shipped through MeshNodeStreamCache's per-path write queue as the response cell's toolCalls leaf. toolCalls is a JSON array, which RFC 7396 replaces wholesale, so a stale patch base gets the whole list refused and the stamp with it. Same queue and same window as the Status = Completed + Text = "Generating response..." cell — root-caused in #2482. Not measured for this test specifically, so it is a lead, not a claim; but it is not a teardown defect.

    The tell to grep BEFORE attributing anything to activation/teardown

    [MergeGuard] <path>: refused stale/reordered cross-hub write to '<key>'
                 (changed since the writer's base) — kept the newer live value.
    

    Already a Warning on the owning hub, and it does reach the trx of other assemblies (PluginCatalog.Test, Hosting.Monolith.Test, Threading.Test, AI.Test in run 33045642840). If it is present, the failure is a silently-refused write leaf, not a lifetime problem. Note the write still acks Success in that case — the owner NACKs Conflict only when nothing landed, and the auto-stamped lastModified almost guarantees something lands. So "no error anywhere" is not evidence that the write was fine.

    🚨 MeshWeaver.Hosting.Orleans.Test produces no per-test output in CI

    All 223 results in its trx have an empty StdOut — not just the failing one — and the shard's collected-logs/_meshweaver-test-trace.log did not cover the failure window in the run I checked (log starts 06:35:38; the failure ran 06:34:37–06:34:51). So an Orleans red in CI gives you the assertion string and nothing else, which is a large part of why this family keeps being attributed by inference rather than by reading. Worth fixing in its own right; it would have saved most of the effort on #2346.

    For the record, this assembly is green locally for me — full suite, Release, DOTNET_PROCESSOR_COUNT=4: 223/223 in 87 s, twice (before and after an unrelated change). So it does not reproduce on macOS/arm64 at 4 cores.

  6. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Fourth recurrence — and this one is on main, with a HOST_CRASHED marker

    Run 33101750253, main at f4b48f5d (the #2515 merge), 2026-08-27:

    Run tests (shard 3)
      MeshWeaver.Hosting.Orleans.Test.OrleansGrainTeardownStragglerTest
        .GrainLifetimeCallbacks_AfterActivationIsInvalid_AreGracefulNoOps_NotThrows [FAIL]
      HOST_CRASHED
    

    Previous recurrences since #2270 closed this on 2026-08-26 12:55 were on PRs (#2476, #2484, and one other). This is the first on main, which means it is no longer only a merge-blocker — it reddens the trunk.

    Attribution, structural

    f4b48f5d's diff is seven files: TransientNodeProbe.cs, VirtualDataSource.cs, MeshNodeStreamExtensions.cs, two docs and two new tests. The failing test file contains zero occurrences of VirtualDataSource, TransientNodeProbe, GetMeshNodeOutcome or FutuRe. The changed code is reachable only from a data-source/probe path; this is a grain-lifetime teardown callback.

    🚨 The genuinely new information: HOST_CRASHED

    The marker shipped this afternoon in #2505, and this is its clearest firing yet. It means the test host died rather than merely failing an assertion — and under the pre-#2505 reporting a host that died after streaming results was indistinguishable from a pass.

    That reframes the whole history of this issue. Every prior occurrence was read as "a 30 s wait expired", and #2270's fix was designed against that reading. But a crashing host and an expiring wait are different failures, and until today the run could not tell them apart. The earlier evidence for this issue should be treated as ambiguous on that point, not as established.

    Two consequences worth acting on:

    1. Whoever resumes this should re-read the pre-An Orleans failure can be read: the window is traced, silo faults are recorded, and a crashed host is a failed result (#2495) #2505 occurrences knowing the timeout may have been a symptom of the crash rather than the failure itself.
    2. The measured fact from the earlier investigation still stands and now matters more: the activation leaves the catalog in 0.10 s when healthy, so a 30 s linger is a genuine stall, not a mis-observation — and a host that dies mid-teardown would produce exactly that stall.

    Standing candidate, still unconfirmed

    MessageHubGrain.DeliverMessage (~line 686) hands Orleans a TaskCompletionSource-backed Task whose only terminal for the never-ready case is produced inside OnDeactivateAsync — the callback Orleans blocks behind in-flight requests.

    🚨 One correction to that candidate, measured today during the #1742 work: it is bounded — BuildActivationChain's Amb timer terminates _hubReadyRaw at 30 s on every path except an enrichment that hangs unbounded. So the circular wait is real but has an exit, and the 30 s bound is suspiciously equal to this test's budget. That coincidence is worth investigating rather than dismissing.

    Not re-running, not merging past it.

  7. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Root cause: the wait DEADLOCKS on the grain's own turn scheduler — the 30 s is the Timeout, not a slow teardown

    PR #2527. Maintainer, today: "totask? this is deadlock" — that is the mechanism, and the
    UnobservedTaskException → HOST_CRASHED recorded in the fourth recurrence above is what the
    deadlock does on its way out, not the failure itself.

    The chain

    1. CompleteActivation builds the grain's hub .WithTaskScheduler(grainScheduler) — so the hub's
      action block, and therefore its disposal, run on the grain's own ActivationTaskScheduler.
    2. Rx's ToTask() creates its TaskCompletionSource without
      RunContinuationsAsynchronously
      . TrySetResult therefore resumes the awaiter inline on the
      signalling thread
      .
    3. So await hub.DisposalCompleted…ToTask(ct) at line 90 resumed the rest of the test method
      inline on the deactivating grain's turn scheduler.
    4. The next statement held that scheduler for 30 s, polling
      IManagementGrain.GetDetailedGrainStatistics() for the very deactivation whose completion
      (ActivationData.FinishDeactivating) needed the scheduler being held.

    It is also sticky: with no SynchronizationContext, await captures TaskScheduler.Current,
    so one inline resumption routes every later await in the method onto the same scheduler. Fixing
    only the last wait would have left the trap armed at the first.

    The signature was in the number all along

    Every occurrence stalled at exactly 30 s — line 98's Timeout budget — never a distribution
    around it. The earlier measurement in this thread says a healthy activation leaves the catalog in
    0.10 s. A wait that always lands precisely on its budget is a deadlock; contention produces a
    spread. That is why every fix aimed at the timeout was aiming at the thermometer.

    Why the documentation kept this alive for four rounds

    IMessageHub.DisposalCompleted's own remarks prescribed the crashing shape:

    "At a genuine async edge (test teardown, grain deactivation) bridge once with
    DisposalCompleted.FirstOrDefaultAsync() / .ToTask()."

    "test teardown, grain deactivation" is exactly where it crashed. Replaced, leading with the
    deadlock.

    The fix

    • GrainDeactivationCompleted — the signal that did not exist, which is why there was a poll.
      MessageHubGrain publishes it from Orleans' own IGrainContext.Deactivated, whose completion
      source ActivationData.FinishDeactivating sets on its last line — after
      UnregisterMessageTarget() removed the activation from the catalog and DisposeAsync() set
      State=Invalid (verified against Orleans 10.2.2; the test now asserts that ordering instead of
      assuming it). AsyncSubject: fires once, replays to late subscribers.
    • ReactiveCompletion.ObserveCompletion — for signatures that are not ours. Subscribes with an
      error arm, and completes its task with RunContinuationsAsynchronously, which is the line that
      stops a caller resuming on the scheduler that signalled.
    • The poll, its 30 s Timeout, and all four .ToTask() bridges in the test are gone. The catalog
      check survives as one direct call — a question, not a wait.

    Local: the straggler test completes in 1 s; MeshWeaver.Hosting.Orleans.Test 215/215.

    DisposalWaitBridgeTest pins it with controls in both directions —
    TheOldToTaskBridge_ResumesItsCallerInlineOnTheSignallingThread asserts the defect, and
    LateFault_ThroughTheOldToTaskBridge_ReachesNobody asserts the second-order loss.

    🤖 Generated with Claude Code

  8. added a commit that references this issue on Aug 27, 2026
  9. rbuergi commented on Aug 27, 2026

    @rbuergi
    ContributorAuthor

    Merged as #2527 (9fba37ced), CI green.

    One correction to my comment above, which described .ToTask() as "settles once and then cannot
    observe anything"
    : that is the second-order effect. The primary failure is the deadlock, and the
    distinction is what made four previous fixes aim at the wrong thing. The mechanism as it now stands
    in the code and docs:

    CompleteActivation builds the grain's hub .WithTaskScheduler(grainScheduler), so its disposal
    signals on the grain's own turn scheduler. Rx's ToTask() completes its TaskCompletionSource
    without RunContinuationsAsynchronously, so the awaiting test method resumed INLINE on that
    scheduler and then held it for 30 s waiting for the deactivation that needed it. The unobserved
    fault, and the HOST_CRASHED marker, are what the deadlock produced on its way out when the
    Timeout finally settled the task over in-flight catalog queries.

    The tell was in the number the whole time: always exactly 30 s, never a distribution around it,
    against a measured healthy departure of 0.10 s.

    DisposalWaitBridgeTest pins both directions, including controls that assert the OLD shape's
    behaviour (TheOldToTaskBridge_ResumesItsCallerInlineOnTheSignallingThread,
    LateFault_ThroughTheOldToTaskBridge_ReachesNobody), so nobody has to take the mechanism on trust.

    Follow-up #2538 carries the Copilot-review fixes that did not make the merge window — chiefly a real
    defect #2527 introduced (teardown resolved its logger from DI after Dispose(), which can throw
    out of the reporting path) plus ConfigureAwait(false) on the three teardown awaits, closing the
    same hazard from the entering side: await captures TaskScheduler.Current absent a
    SynchronizationContext, so a teardown entered from a hub scheduler could still carry itself back
    onto one.

    🤖 Generated with Claude Code

  10. added 3 commits that reference this issue on Aug 30, 2026
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

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions