InstanceSyncPushTest DELETE-push test times out on main and unrelated branches — the change event is dropped at 5.5s, the wait gives up at 30s #1616

Activity

1. rbuergi commented on Aug 14, 2026

   

   rbuergi

   on Aug 14, 2026

   ContributorAuthor

   More actions

   An isolated loop does not reproduce it — the instrument is a full shard.

   flake-repro.yml in rate mode, 40 iterations each, same filter, run on both arms:

   arm	result
   main (31836446824)	0 failures in 40
   a branch that had just failed on it in CI (31836444718)	0 failures in 40

   So the failing condition is not in the test alone. It needs the shard around it — the other projects, the load, the contention — which matches where it actually fails: shard 0 of the full run, after MeshWeaver.Hosting.Orleans.Test (160 tests, 163 s) and MeshWeaver.Autocomplete.Test have just run in the same job.

   Two consequences worth writing down before anyone chases this:

   • A green loop is not evidence of a fix here. Anything measured on flake-repro alone will read clean whether it works or not. Until the repro moves into the loop, the only instrument is the shard, and the only honest measure is occurrences across real runs.
   • Making it reproduce is the first piece of work, not the fix. The most likely lever is the load the shard supplies: DOTNET_PROCESSOR_COUNT=4 on the 2-vCPU runner has reproduced this class before. Getting it to fail on demand is what turns everything after it into measurement instead of guessing.

   Same shape as #890, where a filtered loop stayed green and only a full shard reproduced.
2. rbuergi commented on Aug 14, 2026

   

   rbuergi

   on Aug 14, 2026

   ContributorAuthor

   More actions

   Folding in #1617 (same test, filed independently 4 minutes later)

   Two findings from there that this issue did not have, both worth keeping:

   The timing-margin explanation is refuted, with numbers. InstanceSyncTestBase overrides every interval to be tight — DrainDebounce = 50 ms, PullInterval = 200 ms, RetryInitial = 100 ms, RetryMax = 400 ms — so the 30 s wait covers roughly 150 pull attempts and 75 retry probes. The drain did not arrive late; it never produced a DELETE at all. That kills "widen the bound" on arithmetic rather than on principle.

   A concrete hypothesis for the drain path (stated there as unverified, and repeated here as such):

   The test's sequence is: go offline → accumulate a content change → RecentlyDeletedRegistry.MarkDeleted("theta/doc") (synchronous, emits no change event) → reconnect → expect the drain to convert the pending push into a DELETE.

   A drain attempt that read the local node before MarkDeleted landed could complete after Remote.Unreachable = false, push a stale UPDATE, and clear the pending entry — leaving the remote node present with nothing left to drain.

   That fits everything observed here, including the Dropping DataChangedEvent … the target stream is gone at 5.5 s, and it is load-sensitive in the right way: it needs an in-flight attempt straddling the reconnect flip, which is exactly what a loaded shard supplies and an idle loop does not.

   …and it answers that issue's suggested next step in the negative

   flake-repro.yml at ≥100 iterations on this single test would settle both the rate and the hypothesis

   It does not — measured before it was suggested: 0/40 on main and 0/40 on the branch that had just failed (31836446824, 31836444718). The isolated loop runs one process per iteration with none of the shard's contention, so it cannot reach this. Making it reproduce is the first piece of work; DOTNET_PROCESSOR_COUNT=4 inside a full shard is the lever most likely to get there.

   So the order is: instrument the drain to prove or kill the stale-UPDATE hypothesis (does the drain push an UPDATE where a DELETE was expected?), rather than loop it and read a 0/N as evidence of anything.

   Closing #1617 as a duplicate of this one; nothing from it is lost.
3. rbuergi commented on Aug 17, 2026

   

   rbuergi

   on Aug 17, 2026

   ContributorAuthor

   More actions

   Rate measurement on main — 8 failures in 100 iterations (8%)

   Measured today with flake-repro.yml in rate mode, 100 iterations, on main (not on a feature branch), so the number is independent of any PR:

   RESULT: 8 failure(s) in 100 iteration(s) run (requested 100);
   failing iterations: 12 33 39 47 50 61 64 96
   

   Run: https://github.com/Systemorph/MeshWeaver/actions/runs/32024085067 (test/MeshWeaver.InstanceSync.Test, filter FullyQualifiedName~InstanceSyncPushTest.A_pending_content_change_pushes_a_DELETE_when_the_local_node_is_being_deleted, loglevel=Debug; the failing iterations' trx + blame dumps are on the run's artifacts).

   Two things this pins down:

   1. It is live on main right now, at roughly 1-in-12. That is frequent enough that any PR touching anything has a material chance of catching it — it red-flagged a docs-only PR (docs: which routes ride a module, and which stay in the host #1731, 26 lines of markdown in one embedded .md) an hour ago, which is what prompted the measurement.
   2. The failures are spread evenly across the 100 (12, 33, 39, 47, 50, 61, 64, 96) rather than clustered at the start or end, which argues against a warm-up or resource-exhaustion-over-time explanation and for the per-run race the issue title already describes.

   Posting the number rather than a rerun, per the repo's "measure before attributing" rule — and because a rate measurement is the only form in which a future before/after comparison of a fix will mean anything.
4. rbuergi

   closed this as completedin #1743on Aug 17, 2026
5. rbuergi

   added a commit that references this issue on Aug 17, 2026

   Merge pull request #1743 from Systemorph/fix/1616-instancesync-delete…

   ...

   98c8d3e