Skip to content

CrossProcessChangeFeedTest intermittently reproduces the PRE-FIX signature it was written to detect #2008

Closed

Description

@rbuergi

CrossProcessChangeFeedTest.AWriteInOneProcess_ReachesTheOtherProcessesLiveMirror_WithoutARecycle failed on #1988's shard 1 with the pre-fix signature from #1929 — the failure that fix exists to eliminate:

Expected value to be 2 because the mirror ADOPTS the durable version verbatim.
Against `main` this is where the test fails: the mirror ends at durable+1 — a revision
the store never held (#1432) — because the notification was dropped and the content only
arrived later, through a read-seeded mint. … but found 3.

It passed on re-run, and the six shards are now green.

Why this is not "just a flake"

The assertion is not a timing bound — it is a value comparison, and the value it found (durable+1 = 3) is specifically the shape #1432 describes: converging on content by accident, at a version that exists nowhere, because the notification was dropped and the content arrived later through a read-seeded mint.

So the observed behaviour is the notification losing a race with the read-seeded mint. #1929 closed that path in the steady case; intermittently it still loses. A green re-run tells you the race is not deterministic. It does not tell you it is gone.

What was ruled out

#1988 is not the cause. Its entire diff is one file — memex/Memex.Portal.Shared/MemexConfiguration.cs — adding a response-header middleware (app.Use → OnStarting → set headers) to the HTTP request pipeline. CrossProcessChangeFeedTest builds hubs against a shared store and runs no HTTP pipeline at all. It is rebuilt by the change (MeshWeaver.Hosting.Monolith.Test references Memex.Portal.Shared), so it is not out of reach by dependency — only by behaviour. The re-run passing is consistent with that.

What is NOT evidence, and should not be cited as such

The test passes locally on main — in 2 s for 3 tests, against bounds of [Fact(Timeout = 90_000)] and TestHardDeadline = 120 s. That is far too fast to have exercised the Postgres notify path CI uses, so the local run clears nothing. Anyone reproducing this needs to confirm which path they are actually on before drawing a conclusion.

Suggested next step

Establish the race rather than re-running until green: instrument the ordering between the delivered notification and the read-seeded mint, and assert the notification wins — or make the mint unable to advance the version when a notification for that revision is in flight. The current assertion is correct and should not be relaxed; it caught this.

Reported by me because the fix in #1929 is mine, so this is my debt rather than #1988's.

🤖 Generated with Claude Code

Activity

  1. rbuergi commented on Aug 24, 2026

    @rbuergi
    ContributorAuthor

    Two more CI hits today, both on unrelated RN/JS-client branches (diffs that cannot reach the feed), both shard 1:

    Local attribution on the same tree: 10/10 sequential passes (--filter FullyQualifiedName~CrossProcessChangeFeedTest.AWriteInOneProcess, Release). Matches the issue title: the CI environment intermittently re-samples the dropped-notification → read-seeded-mint path that #1929 closed. Per the repo's race-repro note, DOTNET_PROCESSOR_COUNT=4 locally is the known way to approximate CI scheduling for this family.

    (Reporting to keep the record in one place — both PR runs were re-run rather than "fixed", since the diffs are unrelated.)

  2. rbuergi commented on Aug 24, 2026

    @rbuergi
    ContributorAuthor

    Another occurrence: PR #2184, run 32781941594, shard 1 (2026-08-24 22:15 UTC) — AWriteInOneProcess_ReachesTheOtherProcessesLiveMirror_WithoutARecycle, sole failing test. The branch's diff (Blazor component moves + module publish lanes) has no cross-process change-feed surface, and the same suite ran 757/757 locally on the branch. Rerunning per the standing flake protocol.

  3. rbuergi commented on Aug 25, 2026

    @rbuergi
    ContributorAuthor

    Still live, and the two CI traces are byte-identical — so this is a second deterministic path, not jitter

    Swept the last 300 MeshWeaver Build and Test runs (2026-08-23 → 2026-08-25), reading the
    [FAIL] lines out of every attempt, not just runs whose final conclusion was failure (a
    re-run-to-green hides the attempt that failed). This test is the third most frequent failure in
    that window:

    test failures / 300 runs
    UserDirectoryCompletenessTests.AUserOutsideTheMostRecentlyModifiedPage_… 16
    PartitionRootActivationTest.BarePartitionPath_NoMeshNode_RespondsToPing 4
    CrossProcessChangeFeedTest.AWriteInOneProcess_… 4

    Occurrences: 32722799059/1, 32728115289/1, 32781941594/1, 32891723627/1 — all shard 1.
    (Its Postgres sibling CrossProcessNotifyPgTests.AWriteByAnotherProcess_ArrivesOnThisProcessesPartitionFeed
    also failed once in the window — worth keeping in view, same family.)

    The traces are identical to the character across two independent runs a day apart:

    [B seeded] name=v1 version=1
    [B emit]   name=v1 v=1            writesB=0 readsB=4
    [A durable] version=2
    [B emit]   name=written-in-A v=3  writesB=0 readsB=9      ← the failure
    [store]    v=2 name=written-in-A  writesB=0 readsB=9
    

    against the healthy shape, which is equally invariant (31/31 local runs):

    [B emit]   name=written-in-A v=2  writesB=0 readsB=7
    

    So the failing run does exactly two extra reads and exactly one extra mint. That reproducibility
    is the most useful thing in the issue: this is a second, deterministic path being taken, not a
    timing smear.

    What is now ruled out

    • NOT the "subscribed after the event" class (the defect PR Arm the observer BEFORE the trigger — a hot emission missed has no second chance #2259 established). The trace
      subscription is armed before the write, the mirror is Replay(1).RefCount() with a keepAlive,
      and every emission is printed. There is no emission at v2 that the assertion could have missed —
      the mirror genuinely never held v2.
    • NOT a stale durable capture in the test. WaitDurable returns the first store snapshot
      matching the name, so "the store moved on afterwards" was the obvious test-side explanation. The
      [store] v=2 line printed immediately before the assertion refutes it: the store held 2 at
      assert time, and the mirror held 3. The assertion is correct and must not be relaxed.
    • NOT a write by process B. writesB=0 is counted inside CrossProcessFeedAdapter.Write,
      i.e. below every guard, so the v3 was minted in RAM and never persisted — the 200 ms
      persistence sampler had not fired when the test ended. (Had it fired, the store would have gone to
      3 and the Adopting an already-durable external write MINTS a phantom revision and persists it (deterministic; root cause under #1384) #1432 phantom would have become durable. The test ends before that only by luck.)
    • NOT reproducible locally: 30/30 sequential green with DOTNET_PROCESSOR_COUNT=4, Release,
      isolated — every run the healthy readsB 4→7 / v=2 shape. Matches the earlier 10/10 comment.

    The mechanism this points at — a hypothesis with a code path, not a guess

    AdoptPersisted is careful not to mint (UpdateOwn(..., adoptPersisted: true) skips
    NextVersion and records the durable version in PostCommitFlushRegistry). But the value it
    commits still passes through the data source, and MeshNodeTypeSource.UpdateImpl re-stamps it:

    var alreadyAdvanced = u.Node.Version > u.PreviousVersion && (!isOwn || u.Node.Version >= ownFloor);
    return u.Node with { Version = alreadyAdvanced ? u.Node.Version : MeshNode.NextVersion(floor) };

    PreviousVersion comes from _lastSaved, and _lastSaved is written from two places that are
    not ordered against the workspace's own store
    :

    • BuildInstanceCollection sets it eagerly, when the collection is BUILT — before the workspace
      has applied it;
    • UpdateImpl sets it at the end of a commit.

    The entity-less notification wakes two consumers in process B that both re-read the same durable
    row — the per-node hub's coalesced re-read (SubscribeToOwnDeletion's reReadTrigger) and the
    routing/catalog leg feeding _ownNodeStream. Those two reads are, I believe, the +2 that separate
    the failing trace from the healthy one. If the routing leg wins and builds a collection at durable
    v2 — setting _lastSaved = {v2} while the workspace store is still at v1 — then:

    1. the re-read's AdoptPersisted(v2) sees current.Version == 1, so the forward-only guard lets it
      through and it commits;
    2. UpdateImpl diffs the incoming v2 against _lastSaved already at v2. It still counts as an
      update, because the version-ignoring comparison is record Equals, which is reference-based on
      Content
      — two deserializations of the same row are not equal;
    3. PreviousVersion == Node.Version == 2 ⇒ alreadyAdvanced == false ⇒ Version = NextVersion(2) = 3.

    That produces precisely what the trace shows: one emission, at durable+1, carrying the durable
    content, with nothing written to the store — "converging on content by accident, at a version that
    exists nowhere", which is the #1432 wording this test was given.

    This is a hypothesis. It explains every observable (the exact +2 reads, the single v3 emission,
    writesB=0, the store at 2) and it names a real window in the code, but it has not been reproduced.
    I am deliberately not shipping a speculative change to the own-node versioning core on that basis:
    MeshNodeTypeSource's stamping logic already carries the scars of #325, #590, #1432 and the
    2026-07-30 refusals, and a wrong move there is write loss rather than a flaky test.

    What would settle it in one CI run

    Both lines needed already exist at LogDebug and cost nothing to turn on for this assembly:

    • MeshNodeTypeSource.UpdateImpl: adds={Adds}, updates={Updates}, deletes={Deletes}
    • MeshNodeTypeSource[{HubPath}]: durable activation seed {Outcome} (version={Version})

    A failing run that shows a second own-node collection build at version 2 before the adoption's
    UpdateImpl confirms the hypothesis; one that does not, kills it. Note the test's ILogger output
    goes to XUnitFileOutputHelper's file rather than to xUnit's console output, which is why none of
    it appears in the CI logs today — that alone is worth fixing before the next attempt at this issue.

    If it is confirmed, the fix is not a wider bound but a rule with a name: an own-node update whose
    version is already recorded DURABLE (PostCommitFlushRegistry) is an observation, not an unminted
    edit — never re-stamp it.
    That is exactly the discrimination AdoptPersisted already makes one
    layer up; the layer underneath does not make it.

  4. rbuergi commented on Aug 25, 2026

    @rbuergi
    ContributorAuthor

    Follow-up on the sibling named above: the Postgres one turned out to be a different defect, so it now has its own issue — #2281, fixed in #2286. Its failure is a 30 s TimeoutException (no notification at all), not a wrong version, and the cause is that CrossProcessNotifyPgTests gated on pg_stat_activity — which reports the CONNECTION, while LISTEN mesh_node_changes runs one statement later. The gate went green inside the window it existed to close, and Postgres never replays a NOTIFY.

    Recording it here only so nobody folds the two together while working this one: #2008 is not that. Its notification demonstrably arrives (the mirror converges on the right content); what is wrong is the version it converges at.

  5. rbuergi commented on Aug 25, 2026

    @rbuergi
    ContributorAuthor

    Local reproduction attempts, for the record (all -c Release, DOTNET_PROCESSOR_COUNT=4, on ed4588222):

    • 30/30 sequential, isolated filter — every run the healthy readsB 4→7 / v=2 shape.
    • 1 co-tenant run (every class in the assembly whose name starts with C, so the test runs alongside neighbours rather than alone) — also healthy, same shape.
    • The full-assembly control could not be completed locally: the test host crashes part-way through MeshWeaver.Hosting.Monolith.Test (The active test run was aborted. Reason: Test host process crashed), twice, ~35 tests in and unrelated to this test. CI splits the assembly across two parts and does not hit it. That is a separate local-only obstacle, but it is worth knowing that "I ran the full assembly locally" is not currently an available control for anything in this assembly — which matters because an isolated run discriminates nothing for a full-suite-only failure.

    So: not reproduced. The analysis in the previous comment rests on the two CI traces being byte-identical (readsB 4→9, one emission at v=3, store at v=2, writesB=0) and on the code path, not on a local red.

  6. rbuergi commented on Aug 25, 2026

    @rbuergi
    ContributorAuthor

    On the suggestion that this and the PostgreSQL cross-process test are one mechanism: they are not, and the discriminator is in the two failures' own text.

    "The announcement was delivered and then mis-applied" and "the announcement was never delivered" cannot be the same defect, and #2281 is now closed by a deterministic red/green (#2286) that leaves this one untouched. Same area, same night, two mechanisms.

    Recording it because the pairing is a natural thing to assume, and assuming it here would send the next investigator looking at the wire — which is the half that works.

  7. rbuergi commented on Aug 26, 2026

    @rbuergi
    ContributorAuthor

    A correction to the hypothesis's mechanism (not the fix), plus a diagnostics-visibility PR

    Read through the mechanism the last comment's hypothesis rests on — a second own-node reconcile
    path (the ROUTING leg's _ownNodeStream re-resolving on notification, invalidated by
    PathResolutionService) that re-emits into MeshNodeTypeSource.BuildInstanceCollection,
    bypassing UpdateImpl's diff/version-stamping, racing SubscribeToOwnDeletion's
    reReadTrigger → AdoptDurable → AdoptPersisted path.

    That specific mechanism does not apply to this test as stated. MonolithRoutingService.CreateHub
    supplies the routing leg's _ownNodeStream as a one-shot Observable.Return(enriched):

    // src/MeshWeaver.Hosting.Monolith/MonolithRoutingService.cs
    var ownStream = Observable.Return(enriched);
    var createdHub = Mesh.GetHostedHub(address, c =>
        enriched.HubConfiguration!(c.WithOwnNodeStream(ownStream)));

    with the comment: "One-shot is fine on Monolith — cross-hub MeshNode updates flow through
    IDataChangeNotifier / IMeshChangeFeed already."
    That stream emits once, at hub activation, and
    completes — well before the write this test exercises happens (process B's mirror is already
    seeded and live by the time A writes). So for the event this test asserts on, Initialize()'s
    .Concat(_ownNodeStream...) leg contributes nothing further, and BuildInstanceCollection is not
    re-entered on this path after activation. The only live reconcile at that point is
    SubscribeToOwnDeletion's single reReadTrigger → AdoptDurable → AdoptPersisted → UpdateOwn(adoptPersisted: true) chain, which — walking UpdateImpl's diff — looks correctly
    guarded (alreadyAdvanced holds because the adopted version is strictly above PreviousVersion).

    I believe the "two independent re-read consumers" shape in the hypothesis describes Orleans'
    PathResolutionService-memoized AddressResolution, invalidated by "the per-silo change feed"
    (silo terminology, and MessageHubGrain.cs also touches WithOwnNodeStream) — not Monolith, which
    is what CrossProcessChangeFeedTest actually runs. Recording this so the next investigator doesn't
    re-derive it, and doesn't waste time confirming/refuting a mechanism that can't fire here.

    I have not identified the actual mechanism. readsB going 4→9 instead of the healthy 4→7 (two
    extra reads) still needs an explanation, and I don't have one that survives the one-shot-ownStream
    correction above.

    What I did ship: #2348 — process B's diagnostics now reach captured output

    Confirmed empirically that process B (BuildSecondProcess) had zero logging providers —
    services.AddLogging(l => l.ClearProviders()) with nothing added back — so every ILogger call in
    process B, including the two MeshNodeTypeSource.LogDebug lines this issue's earlier comment named
    as "cost nothing to turn on," went nowhere: not xUnit output, not the file, regardless of level.
    That's a stronger defect than "goes to the file instead of the console" — it's "goes nowhere at
    all" — and it means every occurrence to date, including the ones analyzed above, ran with zero
    visibility into process B's own-node reconcile.

    #2348 wires process B's logging the same way process A's already is (TestBase's
    XUnitFileLoggerProvider, pointed at the shared FileOutput) and grants
    MeshWeaver.Graph.MeshNodeTypeSource a Debug override for both processes (appsettings.json for
    A, an in-memory IConfiguration for B, since B never loads the JSON file). Verified locally that
    process B's diagnostics now reach the captured test output where they were previously completely
    absent.

    Not a fix — no production code changed. This issue stays open until a CI occurrence with the new
    diagnostics on lands and the actual mechanism can be read off it.

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

    @rbuergi
    ContributorAuthor

    First reproduction WITH process B's diagnostics — #2348 worked

    This issue asked for exactly one thing to settle it: "the two LogDebug lines already in MeshNodeTypeSource, which today never reach any CI artifact for process B." #2348 (merged 5b1901fb6) restored process B's logging providers — it had services.AddLogging(l => l.ClearProviders()) with nothing added back, so every ILogger call in that process went nowhere, including on every failing run.

    The flake has now recurred on a run that carries the fix — PR #2352, shard 2, run 32964944158, 2026-08-26 ~11:53Z. (#2352's diff is deploy/helm YAML only and cannot reach this assembly; it is an unrelated carrier.)

    The assertion

    MeshWeaver.Reactive.Assertions.AssertionException :
      Expected value to be 2 because the mirror ADOPTS the durable version verbatim.
      Against `main` this is where the test fails: the mirror ends at durable+1 — a revision the
      store never held (#1432) — because the notification was dropped and the content only arrived
      later, through a read-seeded mint. Converging on content by accident, at a version that exists
      nowhere, is not a mirror learning of a write, but found 3.
    

    Expected 2, found 3 — durable+1, precisely the shape this issue describes.

    What process B actually did (previously invisible)

    [11:53:04.432] MeshNodeTypeSource: Created for hubPath=TestData/cross-proc-34b038d7…
                   (routingSuppliedStream=True)
    [11:53:04.436] MeshNodeTypeSource[…]: durable activation seed read (version=1)
    [11:53:04.519] MeshNodeTypeSource: Opening gate for … — node Active via update
    [11:53:04.519] MeshNodeTypeSource.UpdateImpl: adds=0, updates=1, deletes=0
    

    Three things worth reading off that, which were unavailable before:

    1. routingSuppliedStream=True — process B's MeshNodeTypeSource was constructed with the routing-supplied _ownNodeStream. test: make process B's own-node diagnostics reach CI output (#2008) #2348's investigation established that on Monolith this is a one-shot Observable.Return(enriched) that completes at activation, so it cannot be the source of a later re-emission.
    2. durable activation seed read (version=1) — B seeded from durable at v1, i.e. before the write under test.
    3. UpdateImpl: adds=0, updates=1, deletes=0 — B classified the arriving change as an update, not an add, and the gate opened "node Active via update". So the path that ran is the update branch, and the mirror still landed on 3 rather than adopting durable's 2.

    That narrows it: the mirror did not miss the event entirely — it processed an update — but ended a revision above durable, which is the "content arrived through a read-seeded mint rather than the notification" reading this issue proposed.

    Caveats, stated rather than glossed

    • This is one occurrence. The issue measures ~1.3% (4/300), so a single trace can mislead; treat the above as the first data point of a set, not a proof.
    • I have not re-derived the timing of the writer side against B's clock here — the log excerpt above is B's own sequence.
    • The run's logs will age out with GitHub's retention, so anyone picking this up should pull the full shard-2 log now rather than later.

    #2008 stays open. #2348 was observability only and said so; this comment is the payoff, not a fix.

  10. rbuergi commented on Aug 26, 2026

    @rbuergi
    ContributorAuthor

    Root-caused, deterministic red/green, fix in #2392 — plus a correction to the last comment

    First the correction, because it points the next reader the wrong way

    The MeshNodeTypeSource Debug lines quoted in the #2348 payoff comment as "what process B actually did" are process A's.

    #2348 gave process B a logger provider, but not AddConfiguration — and the level that decides whether a record is emitted at all lives in LoggerFilterOptions, which ILoggerFactory consults before any provider and which defaults to Information. So B's Warning/Error records did start arriving (a real improvement on "no providers at all", so the change was not wasted), while every LogDebug the same change added — including the two own-node reconcile lines the exercise was for — was still dropped by the factory.

    Measured rather than argued: resolving ILogger<MeshNodeTypeSource> in both processes and reading IsEnabled(Debug) gives A: true, B: false. That also explains why the trace read as uninformative — routingSuppliedStream=True, seed read (version=1), UpdateImpl: adds=0, updates=1 are exactly what a healthy local run prints, because they describe A's per-node hub activating to serve the write. #2392 adds l.AddConfiguration(...); with it you get two Created / durable activation seed read pairs per run instead of one.

    The mechanism

    A per-node hub writes its own activation seed back to storage — the durable row it just read.

    MeshNodeTypeSource.Initialize builds two instance collections back to back (the durable seed, then the routing-supplied leg) and each stamps OwnNodeCache.PersistedSnapshot. That stamp is one slot, and the persistence sampler's initial-load echo suppression is a reference comparison against it. So by the time the workspace delivers the seed emission to the sampler, the slot already holds the routing instance: the seed fails the reference test and is dispatched as a SaveMeshNodeRequest as if it were a local edit.

    Instrumented directly (raw file probe, both processes tagged, so it depends on none of the logging above):

    BIC hub=TestData/x v=1 hash=44597241            <- emission #1, the durable seed
    BIC hub=TestData/x v=1 hash=60718826            <- emission #2, the routing leg — overwrites the stamp
    SAMPLER-IN   proc=B v=1 refEq=False hash=44597241 persistedHash=60718826
    SAMPLER-POST proc=B v=1
    HANDLE-HW    proc=B v=1 hw=0
    WRITE        proc=B v=1                          <- the mirror writes back the row it just READ
    

    On a quiet node that is an equal-version rewrite and invisible. When A's real write lands first it is a strict version regression → MonotonicWriteGuard refuses it → AdoptDurableTruth (correctly, for a hub that has something of its own to save) rebases the refusing owner at durable + 1 → the mirror holds a revision the store never held. Whether the echo or the real write got there first is the coin flip that made this read as a ~1.3% flake.

    It also accounts for the two observables this issue singled out as its best clues, neither of which had an explanation before:

    • readsB 4→9 instead of 4→7 — the two extra reads are the guard's verification read plus the rebase's read. Not a second reconcile consumer.
    • writesB=0 while the guard still fired — MonotonicWriteGuard.ResolveConflict returns early on IsLatestUnchanged without calling the inner adapter, which is also precisely what merged=(none); latest-wins (stale values DROPPED)=Name in the CI log reported.

    So the earlier hypothesis was pointing at the right file and the wrong mechanism: there is no second own-node reconcile consumer, and UpdateImpl never re-stamps the adoption. The two builds are both inside Initialize, and what they corrupt is the echo-suppression stamp, not the version.

    The fix

    DurableSeed records the version it read on PostCommitFlushRegistry, so HandleSaveMeshNode and the dispose-time FlushPendingOwnSave drop the echo — the suppression MeshNodeStreamHandle.AdoptPersisted already applies to the other durable-observation path (a storage change notification). The activation seed was the one durable read that did not.

    Through a new RecordObservedDurable, not Record: Record is the flush's completion signal and resolves any unresolved Claim with "persisted: true". A read is not a completed write, and resolving someone's in-flight claim would tell a deferred SaveMeshNodeRequest to drop itself for a write that may still fail — trading a duplicate-write bug for a lost-write one. A real edit is unaffected: UpdateImpl mints it strictly above the seed.

    Both directions, measured

    New test CrossProcessChangeFeedTest.AMirroringProcess_NeverWritesTheNode_NotEvenItsActivationSeed. It uses two nodes deliberately: the mirrored node under test is never written by anyone, so nothing can rescue B's echo — asserting on a path A also writes lets B's own AdoptPersisted raise the high-water first and turns the red back into the same coin flip this issue is (verified: that shape passed on unfixed code). A sibling node A does write supplies the wait.

    check result
    new test, framework fix reverted 10/10 RED ([B writes] seed=1 clock=0)
    new test + the 3 existing ones, fix applied 10/10 GREEN
    full MeshWeaver.Hosting.Monolith.Test, fix reverted 773 passed, the only failure is the new test
    full MeshWeaver.Hosting.Monolith.Test, fix applied new test green
    MeshWeaver.Graph.Test 1607/1607

    Environment: macOS, DOTNET_PROCESSOR_COUNT=4.

    This is a production defect, not a test artefact: every per-node hub activation re-persisted its own row, and at two replicas that echo is a live lost-update hazard on any node the other replica is writing — the same shape as the rival-mirror case this test class was written for.

  11. added a commit that references this issue on Aug 26, 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