Repository navigation
Flake on main: FaultedInit_ReachesTerminalFailedState_AndAnswersFast — hub reaches FAILED in 4 ms, the probe request is never rejected (15 s timeout) #2625
Description
What
MeshWeaver.Data.Test.DataContextInitFaultedTest.FaultedInit_ReachesTerminalFailedState_AndAnswersFast (added by #2528's fix, 5204e0fd4, 13:55Z) failed on main at 22722c2a (the #2615 merge), shard 4, run 33181004785 — and passed on main at 5610756 35 minutes earlier. Same test source both times ⇒ a race, not a regression of the test.
What the log says
[15:03:13.197] [SYNC_STREAM] OnError for BEWp1B6u9E6s7qW2AH2R3w (Reference=FaultyItem, Owner=ds/lgZYlcRS80eNi5DNLEG4aQ)
[15:03:13.197] Data source stream lgZYlcRS80eNi5DNLEG4aQ errored
[15:03:13.197] Hub sync/-BGwAgrYBkWk0QMqCgQo1Q initialization failed — a BuildupAction faulted (InvalidOperationException: boom during initial data load). Hub is now in FAILED stat…
[15:03:13.201] [SYNC_STREAM] OnError for Bp-yJrv0rkm-lHu7hh55-A (Reference=FaultyItem, …)
[15:03:28.309] === TEST FAILED: Did not expect value to be of type TimeoutException because a faulted init must be answered FAST by the rejection handler …
The host hub reaches FAILED 4 ms after class init. The client's ProbeRequest (Observe … FirstAsync().Timeout(15s)) then gets nothing for 15 s — not a rejection, not a DeliveryFailure. So one of:
- the request arrived while the hub was still initialising, was deferred, and the faulted arm transitioned to FAILED without flushing the deferred buffer through the rejection handler — the queued request is simply dropped; or
- the request arrived after FAILED and the FAILED path answers only requests that passed through the init gate, so a cold arrival is not rejected.
Either way the assertion's own message names the defect exactly: "the faulted arm skipped the settle body and left the gate shut". It is the wedges-to-zero branch the watchdog is supposed to guarantee.
How to pin it
Run MeshWeaver.Data.Test in bulk (this reproduces in the whole-project run, not in isolation — same class of bug as /debug's "hangs reproduce only in bulk"). Trace MeshWeaver.Messaging and read the MESSAGE_FLOW tags for the ProbeRequest: if there is a Deferring on-target/Buffering line and no ROUTING_TO_LOCAL_EXECUTION or rejection after initialization failed, it is (1).
Not a band-aid
Do not widen the 15 s timeout — the test is asserting speed on purpose. Fix the faulted arm so it rejects both the deferred backlog and every later arrival.
Refs: #2528 (the fix that introduced the test), #2616 (the other post-#2598 flake population — check whether it shares the deferred-buffer edge).
Activity
rbuergi commentedon Aug 28, 2026
Duplicate of #2614 (mine, filed 14:0x) — consolidating here, because your diagnosis is the better half
Same test, same run, same shard. I am closing #2614 as a duplicate and moving its evidence here rather than the other way round: you found the mechanism (hub FAILED in 4 ms, probe never rejected) and I only had occurrences and an attribution argument.
Three things from #2614 that are not in this issue yet:
1. There is an EARLIER occurrence — this is the second, not the first
So the sequence is 12:52 on a PR → 14:36 on main, roughly two hours apart, on a test that landed at 13:55Z the same day… which means the first occurrence predates the test's own merge to main — it fired on a PR that had merged main in. Two hits inside two hours on unrelated commits is a rate worth the priority you are giving it.
2. It does not reproduce locally, which is worth knowing before anyone tries
origin/main, 25 consecutive runs,DOTNET_PROCESSOR_COUNT=4(the setting that has reproduced CI races in this repo before): 25 pass, 0 fail. So the race needs the CI shard's timing, not merely CPU pressure — a local loop is not the way in. Your log-based route is.3. The attribution, so neither PR gets re-blamed
At 12:52 this red was on #2611, whose diff is confined to
MeshWeaver.Graph's NodeType compilation while the test exercisesMeshWeaver.Data's DataContext init — no path between them. Your main occurrence at22722c2asettles it directly: #2611 and #2615 are both exonerated by measurement rather than by argument.One thing I would keep from #2614's framing
The 15 s bound is the wrong lever, and your finding is exactly why: the hub reaches FAILED in 4 ms, so the budget is not marginal — it is irrelevant. The probe is never rejected at all. Widening the timeout would convert a 15-second failure into a 60-second one and hide the very wedge the assertion names ("a timeout means the faulted arm skipped the settle body and left the gate shut"). Worth stating in the issue so the cheap fix is visibly off the table.
Cross-referenced on #1384 as part of that flake population.
rbuergi commentedon Aug 28, 2026
Narrowing from the code (not yet reproduced in bulk):
DataContext.OpenInitializationGatewaits onTask.WhenAll(tasks)where each task isdataSource.Initialized(DataContext.cs:354).GenericUnpartitionedDataSource.InitializedisTask.WhenAll(Streams.Values.Select(s => s.Hub.Started))(GenericUnpartitionedDataSource.cs:314-321) — it waits for the sync child hub to reachStarted, not for the initial load to settle.sync/-BGwAgrY…) loggedinitialization failed … FAILED state; the host never loggedDataContext initialization failedand never opened its gate — the probe was deferred behindDataContextInituntil the test's 15 s expired (the 120 sInitializationTimeouttime-box would have settled it later, as a TimeoutException, i.e. still the wrong answer).MessageHub.cs:561-563:EnterInitializationFailedState+OpenGate→hasStarted.TrySetResult()at line 204) and whatInitializedobserves. Two candidates: (1)Streamsis snapshotted when the getter runs, and the stream/hub is created after →WhenAll(empty)completes clean → the host opens the gate WITHOUT failure and would answer the probe with aProbeResponse(not what was seen, so unlikely here); (2) the child'sStartednever settles on this path — e.g.OpenGate(Initialize)does not reachRunLevel.Startedbecause another gate on the child stays closed, or the FAILED arm'srequest.Failed(...)short-circuits the transition — so the host waits the full time-box.Either way
Initializedshould be a promise about the LOAD (theWithInitializationtask / the stream's firstFullorOnError), not about the child hub's run level — a child that goes FAILED must fault the parent's init, not merely "start". Bulk repro withMeshWeaver.Messaging: Tracewill show which of the two it is.rbuergi commentedon Aug 28, 2026
Duplicate of #2614 (same test, same shard-4 red, filed earlier from the #2618 run). The code narrowing in my comment above —
GenericUnpartitionedDataSource.Initializedwaits on the sync child hub'sStarted, not on the load; the child's FAILED arm opens its gate without faulting the parent — moves to #2614. Closing this one.rbuergi commentedon Aug 31, 2026
Recurred 2026-08-31 ~22:5xZ on #2922 (shard 4) — a 4-file workflow/tooling PR that cannot reach MeshWeaver.Data.Test, so the ambient race is still live after this issue's previous close. Rerunning the shard for the PR (attributed, not investigated-away); the race itself needs the deterministic repro this issue's history calls for.
rbuergi commentedon Sep 1, 2026
Root cause found and PINNED WITH A DETERMINISTIC REPRO — it is (b), and it is a constructor-ordering race
PR #2946.
Your narrowing was right:
Initializedhangs because the child'sStartednever settles. Candidate(a) — an empty
Streamssnapshot — is ruled out:TypeSourceBasedUnpartitionedDataSource.Initializecreates the stream eagerly, before
DataContext.InitializeDataSourcesreadsInitialized.The mechanism
MessageHubConfiguration.Buildends withStartMessageProcessing(), and that method postsInitializeHubRequest. So thesync/…sub-hub is already draining its own init turn — on its ownturn scheduler, another thread — while
SynchronizationStream's constructor is still insideGetHostedHub. And that constructor boundHubonly on the return path:Observable.Throwfaults synchronously on subscribe, so the data source's initial load reachesSynchronizationStream.OnErrorinside that window. There,if (Hub is not null)skipped bothHub.FailStartup(error)andHub.OpenGate(SynchronizationGate)— with no log, no exception:SynchronizationGatenever opens ⇒ the sub-hub never reachesStartedHub.Startednever settles ⇒IDataSource.Initialized(WhenAllover those tasks) hangsDataContext'sDataContextInitgate is never given its answerThat is exactly the log you quoted:
sync/… initialization failed — a BuildupAction faultedat 4 ms,no
DataContext initialization failed for …, and nothing answering the probe.Why 25 local runs found nothing, and how to stage it instead
The window is a few instructions wide, so a repeat loop is the wrong instrument.
HostedHubsCollectionpublishes
HubAddedtwice per hosted hub and the two emissions straddle the window exactly:HostedHubsCollection.Add— insideBuild, beforeSyncBuildupActions, so nothing can havefaulted yet;
GetHub's creationLazy— afterBuildposted the init request, beforeGetHostedHubreturns to the constructor.
Subscribing on the second emission and holding that thread until the sub-hub records its
InitializationErrorpins the interleaving with no timing luck at all.DataContextFaultedInitBeforeStreamHubBoundTest: 30.02 s FAIL before the change (fell through tothe hub's own deferral timeout;
RunLevel=Startingat park release), 69 ms PASS after(
RunLevel=Started).The fix
ConfigureSynchronizationHubnow starts with.WithInitialization(BindHub)— the synchronousoverload, which
Buildruns BEFOREStartMessageProcessing. No window remains: every BuildupActionand every handler on the sub-hub sees a bound
Hub. The same window was a latentNullReferenceExceptionon the success path too (OwnerVersion()readsHub.Version).The residual null-
Hubbranch stays for the constructor's refusal path but is now loud — skippingFailStartupis a wedge, never a no-op, and the silent version is the whole reason this took twomonths to see.
No bound was widened, no watchdog added, no retry, no
catch {}.Written up in
Doc/Architecture/HubInitializationFailure→ "A hub's init runs BEFORE its creator'sconstructor has returned", including the two safe binding points and the
HubAdded-twice recipe./cc #1384 — this is the mechanism for this member of that flake population; #2616 is worth re-checking
against it, since a deferred-forever request is the shared symptom.