Repository navigation
Sync: start the heartbeat early — the 45s stall behind the 2026-07-27 outage - #684
Conversation
… snapshot This is the actual root cause behind today's memex outage. My two earlier fixes (#681, #682) treated it one level too high and neither worked in production — the uncached probe never fired and the self-heal never healed, because both sit on top of the layer that is actually broken. Every recovery path in CreateExternalClient is event-driven: the change feed announces an owner restart and the latch re-subscribes. NOTHING recovered a stream whose owner ACKED the SubscribeRequest and then never delivered the first DataChangedEvent. No announce ever comes, so the latch never trips and the read just waits — in practice until the 45s heartbeat shakes something loose. The comment above the subscribe says so outright: "This is not a retry/watchdog: nothing re-posts on a timer." Measured on memex, from the compile activity log's microsecond timestamps: source discovery 45.20s (healthy mesh) 90.19s (outage — two misses) Roslyn 2.83s 2.6s 45.20s is one HeartbeatInterval to within 200ms. 97% of every compile was a lost Initial waiting for a heartbeat. Types then crossed the 60s settle window and every plugin root served the "did not settle" fallback. The same silence keeps an instance's NodeType stream from ever seeing a fresh build, which is exactly why the overlay self-heal had nothing to fire on and only a process restart cleared it — one bug, three symptoms. So: if nothing has arrived shortly after subscribing, re-send the SubscribeRequest through the SAME proven Resubscribe path. Bounded (3 attempts, 4s apart) — a missed-wakeup nudge, not a retry loop. An owner that genuinely cannot answer already faults the stream through the subscribe's own error path; one that is merely slow satisfies the probe with its first delivery. Take() bounds the timer so it can never become the process-global TimerQueue root the heartbeat comment documents. The load-bearing test is the NEGATIVE one: a healthy stream must never re-subscribe. A watchdog that fires anyway re-creates a sync/{ClientId} hub per stream on the owner's single-threaded action block — the very storm ChangeFeedResubscribeCoalesceTest exists to prevent, and worse than the bug. 289/289 Data tests pass. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
Pull request overview
Adds a bounded “missing initial snapshot” resubscribe probe to JsonSynchronizationStream.CreateExternalClient to recover from the case where the owner ACKs a subscribe but never delivers the first DataChangedEvent, and pins the behavior with a new integration test (including the critical negative “healthy stream never resubscribes” guard).
Changes:
- Add a bounded timer-based probe (
MissingInitialProbe,MaxMissingInitialResubscribes) that triggersResubscribe(...)if no initial delivery is observed shortly after subscribing. - Add
MissingInitialResubscribeTestto ensure healthy streams never trigger the watchdog and to pin watchdog budget/timing constraints.
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
| src/MeshWeaver.Data/Serialization/JsonSynchronizationStream.cs | Introduces the missing-initial watchdog and its configuration constants inside the external-client sync stream path. |
| test/MeshWeaver.Data.Test/MissingInitialResubscribeTest.cs | Adds coverage to prevent resubscribe storms on healthy streams and to pin watchdog bounds. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| var initialArrived = 0; | ||
| keepAlive.Add(reduced.Subscribe( | ||
| ci => | ||
| { | ||
| // Same shape as the version tracker below: TReduced is unconstrained, so read | ||
| // the value as object before null-testing it. | ||
| object? value = ci is null ? null : ci.Value; | ||
| if (value is not null) | ||
| Interlocked.Exchange(ref initialArrived, 1); | ||
| }, | ||
| // Passive tracker (see the version tracker below): never rethrow on the emission | ||
| // thread — the stream's real subscribers own error propagation. | ||
| _ => { })); |
The new test went RED on CI while passing locally, and it was right: on a loaded
runner a genuine cold read outruns a 4s probe, so the watchdog re-subscribed a
HEALTHY stream. That is the dangerous direction, under exactly the condition that
matters — a mass cold start is every deploy, and each re-subscribe creates a
sync/{ClientId} hub on the owner's single-threaded action block. A stall that costs
15s is a slow page; a storm is an outage. When in doubt, be late.
Two changes:
- The probe moves to 15s: still a third of the 45s heartbeat it exists to beat, but
comfortably above the slowest legitimate cold read.
- The test stops measuring machine speed. It asserted an absolute "exactly one
subscribe" BEFORE the idle wait, which is a statement about how fast the runner
served the first payload. The real invariant — and what it asserts now — is that
once data is flowing the count never grows again. An extra subscribe during a slow
start is the watchdog working, not the regression.
289/289 Data tests pass.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…ream behaviour CI failed across THREE shards, and only one failure was my own test: shard 0 ExportImportAccessControlTest.Export_PartialAccess_ExportsOnlyPermittedSubset shard 4 TodoGraphIntegrationTest.ACME_Project_NodeType_CanBeInitialized shard 5 MissingInitialResubscribeTest.HealthyStream_... Those first two were green on this same code an hour earlier, so the watchdog was not just failing to work — it was perturbing unrelated streams. Cause: it rode its OWN reduced.Subscribe to notice the first delivery. An additional early subscriber changes WHEN a ref-counted stream starts, so a stream behaved differently merely by being watched, and my own arrival flag was reading a different activation than the one serving data. The arrival flag now piggybacks the EXISTING passive tracker (the one recording receivedVersion): one subscription, two observations. Nothing else about the watchdog changes. Verified against the exact tests CI broke, not just my own: Data.Test 289/289 ExportImportAccessControlTest 5/5 TodoGraphIntegrationTest 7/7 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Draft — stopping here deliberately, with the diagnosis intactFourth attempt at this tonight. The site is healthy ( What is PROVEN (measured, not inferred)From the compile activity node's microsecond timestamps on memex:
Also proven: What this branch does, and what it got wrongRe-sends the
The remaining failure, and why it may be a design problem
The uncomfortable reading: if a healthy CI stream still hasn't delivered after 15 s, then elapsed time is a poor discriminator between "lost wakeup" and "slow owner" — and any purely time-based watchdog will either fire on healthy streams or arrive too late to matter. If so, the right fix is at the protocol level (an explicit ack/empty-snapshot response, so silence is unambiguous) rather than a timer. That is the question the next person should answer before tuning this number again. Left open
|
…e actual fix
Replaces the re-subscribe watchdog with the thing the evidence was pointing at all
along. Net effect on the file: -34 lines, and the functional change is one line.
Observable.Interval(heartbeatInterval) -> Observable.Timer(FirstHeartbeat, heartbeatInterval)
The tell was always WHERE the data arrives: exactly on a heartbeat. 45.20s of
source discovery on a healthy mesh, 90.19s during the outage, against 2.83s of
Roslyn — 45.20s is one HeartbeatInterval to within 200ms. The owner is not slow; it
holds the delivery until something pokes it, and every other recovery path here is
event-driven, so a stream whose owner acked and then went quiet produces no event at
all and nothing runs until the first heartbeat 45s later.
So poke sooner. The first tick moves to 5s; the cadence is unchanged. It is the same
fire-and-forget [SystemMessage] the stream already sends forever — one extra cheap
message per stream, no new subscription, no new protocol, no state machine.
Deliberately NOT the re-subscribe probe I tried first. Each SubscribeRequest creates
a sync/{ClientId} hub on the owner's single-threaded action block, so a probe becomes
a storm under mass cold start — every deploy — which is the failure
ChangeFeedResubscribeCoalesceTest exists to prevent. CI proved that twice: at a 4s
probe it fired on healthy streams under load, and its extra reduced.Subscribe changed
when ref-counted streams start, breaking ExportImportAccessControlTest and
TodoGraphIntegrationTest in unrelated shards. A heartbeat creates nothing.
The test is a deterministic RED on the old schedule, not a timing race: with the
production 45s cadence configured, a heartbeat inside the test window can ONLY come
from the early first tick. Verified by reverting the one line — the test fails —
then restoring it.
Data.Test 290/290
ExportImportAccessControlTest 5/5 (broken by the previous attempt)
TodoGraphIntegrationTest 7/7 (broken by the previous attempt)
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
rbuergi
changed the title
Rewritten: one line, and it is the actual fixThe re-subscribe watchdog is gone. Net effect on the file is -34 lines, and the functional change is one line: - Observable.Interval(heartbeatInterval)
+ Observable.Timer(FirstHeartbeat, heartbeatInterval)Why this, and not the probeThe tell was always where the data arrives: exactly on a heartbeat. 45.20 s of source discovery on a healthy mesh, 90.19 s during the outage, against 2.83 s of Roslyn — 45.20 s is one So poke sooner. First tick at 5 s, cadence unchanged. Same fire-and-forget The probe was the wrong shape and CI proved it twice: at 4 s it fired on healthy streams under load, and its extra The test is a deterministic red, not a timing raceWith the production 45 s cadence configured, a heartbeat inside the test window can only come from the early first tick. Verified by reverting the one line —
Plus a storm guard (subscribe count never grows) and a bounds check on the constant. |
CI caught a real regression I introduced: HeartbeatFireAndForgetTest configures a
200ms heartbeat, and an unconditional 5s first tick pushed its first beat out to 5s,
so the beats it counts never arrived. The early tick is meant to LOWER the floor for
long intervals, never to delay a short one.
var firstTick = heartbeatInterval < FirstHeartbeat ? heartbeatInterval : FirstHeartbeat;
200ms cadence keeps its 200ms first beat; the 45s production cadence gets its first
beat at 5s, which is the whole fix. Pinned by EarlyTick_NeverDelaysAShorterConfiguredInterval
so nobody re-inverts it.
Also widened the CI headroom in the new test from 5s to 15s — still far below the
45s cadence, so a heartbeat inside the window can only come from the early tick and
the assertion stays a detector rather than a stopwatch on the runner.
Data.Test 291/291
HeartbeatFireAndForgetTest green (the test this commit repairs)
NonExistentOwnerNoHeartbeat… green
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…the runner Only my own two tests were still failing CI; every existing test, including the HeartbeatFireAndForgetTest this branch repaired, was green. The cause was the test, not the fix: both slept a fixed Task.Delay and then asserted, which measures how loaded the runner is rather than what the schedule does. That is the same mistake twice — it is why the first version passed locally and failed on CI. Now it polls to a deadline and exits the moment the beat arrives: 5s locally instead of a fixed 20s, and tolerant of a slow runner. The deadline (30s) stays far below the 45s cadence, so a heartbeat seen inside it can still ONLY be the early first tick — the detector is unchanged in strength. The two integration tests collapse into one: the storm assertion (subscribe count never grows) belongs in the same run as the beat it is guarding, not in a second fixture paying its own startup. Re-verified after the rewrite by reverting the one-line change: the test FAILS on Observable.Interval and passes on Observable.Timer(firstTick, …). Data.Test 290/290 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…ve passed The CI failure was never the fix and never runner load: "Test execution timed out after 5000 milliseconds". This repo enforces a 5s per-test budget, and my test waited for the production 5s beat. It could not pass on any machine, including mine — it only "passed" locally because the local runner does not enforce that budget. The correction improves the product rather than weakening the test: FirstHeartbeat moves onto SyncStreamOptions (default 5s, taken as the sooner of it and HeartbeatInterval). Operators get a knob, and the test configures a 300ms first beat against the production 45s cadence — so the only thing that can deliver a beat inside a 2s deadline is the early tick under test. Runtime: 846ms, from 20s of sleeping. Still a deterministic detector — reverted the one-line change and the test FAILS, restored it and it passes. Data.Test 290/290 (incl. HeartbeatFireAndForgetTest, NonExistentOwnerNoHeartbeatStorm) Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
| total compile | |
|---|---|
| pre-fix baseline (warm system, 21:35Z) | 48 s |
| post-fix (settled system, 02:50Z) | 57 s |
No improvement. A compile attempted a few minutes after the rollout also failed outright with the original symptom — No response received in hub cache/… within 00:01:00 for request SubscribeRequest → target Store/Coupon.
So the hypothesis this PR implements — "the owner withholds delivery until a heartbeat pokes it, so poke sooner" — is not supported by production. Starting the first heartbeat at 5 s instead of 45 s changed nothing measurable. Either the delivery is not actually triggered by the heartbeat post, or something else dominates the 45 s.
What IS still solid
The measurement that started this remains reproducible and unexplained: 45.20 s of source discovery on a healthy mesh, 90.19 s during the outage, against 2.6–2.83 s of Roslyn, with 45.20 s matching HeartbeatInterval to within 200 ms. That correlation is real; my causal story about it was wrong.
What this PR still legitimately contributes
SyncStreamOptions.FirstHeartbeatas a documented, configurable knob (default 5 s, taken as the sooner of it and the cadence).EarlyFirstHeartbeatTest, includingEarlyTick_NeverDelaysAShorterConfiguredInterval— which caught a real regression where an unconditional early tick delayed short cadences and brokeHeartbeatFireAndForgetTest.- No regression: 15/15 CI green, and the ci.1467 rollout did not need the manual scale-to-zero that the previous deploy required (16/16 roots verified rendering).
Recommendation for whoever picks this up
Do not treat the stall as fixed. The next step is to instrument where those 45 s actually go — per-phase timing inside SnapshotSources/GetSources, and a log line when a delivery is satisfied by a heartbeat versus an Initial — rather than another causal guess. I made three of those tonight and each was wrong; the measurement is cheap and would have settled it hours ago.
Reverting is also reasonable if the knob isn't wanted: the behaviour change is one line.
…synced query
A compile needs a POINT-IN-TIME snapshot of its sources. It was taking that snapshot
from the cached SYNCED query, which exists to deliver LIVE updates — a guarantee a
compile does not need and, on a large mesh, pays 45 seconds for.
Measured on memex, same box, same data, same four queries a Store/Coupon compile
issues:
via IMeshService.Query (what MCP `search` uses) ~0.25s counts 16 / 4 / 1
via the cached synced query (what compiles used) 45.20s
45.20s is one SyncStreamOptions.HeartbeatInterval to within 200ms: the synced
subscription misses its Initial and idles until the periodic heartbeat re-delivers.
Roslyn itself is 2.83s, so 97% of every compile was that wait — and types then
crossed the 60s settle window, which is how every plugin root came to serve the
"did not settle" fallback on 2026-07-27.
Everything else was eliminated by experiment BEFORE writing this, which is the part
the earlier attempts skipped:
- the compile path itself 0ms discovery on a fresh mesh (issue #686)
- topology 0ms with ONE silo and with TWO (real AdoNet cluster,
both silos Active) — silo count is not the cause
- scale / ~90 schemas the same queries answer in 0.25s ON memex
- the heartbeat schedule #684 shipped and measured no change (48s → 57s)
- pre-warming enabled on memex, degraded 7 of 16 roots, rolled back
So: direct read FIRST, synced query kept only as a fallback when the direct read
finds nothing. Never the other way round. #682 kept the cache primary and raced a
delayed probe against it — that probe never fired once in production, and this
ordering is exactly what removes the dependency on winning a race.
647/647 Graph, 8/8 Hosting.Monolith compile/pre-warm integration tests.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…synced query (#690) A compile needs a POINT-IN-TIME snapshot of its sources. It was taking that snapshot from the cached SYNCED query, which exists to deliver LIVE updates — a guarantee a compile does not need and, on a large mesh, pays 45 seconds for. Measured on memex, same box, same data, same four queries a Store/Coupon compile issues: via IMeshService.Query (what MCP `search` uses) ~0.25s counts 16 / 4 / 1 via the cached synced query (what compiles used) 45.20s 45.20s is one SyncStreamOptions.HeartbeatInterval to within 200ms: the synced subscription misses its Initial and idles until the periodic heartbeat re-delivers. Roslyn itself is 2.83s, so 97% of every compile was that wait — and types then crossed the 60s settle window, which is how every plugin root came to serve the "did not settle" fallback on 2026-07-27. Everything else was eliminated by experiment BEFORE writing this, which is the part the earlier attempts skipped: - the compile path itself 0ms discovery on a fresh mesh (issue #686) - topology 0ms with ONE silo and with TWO (real AdoNet cluster, both silos Active) — silo count is not the cause - scale / ~90 schemas the same queries answer in 0.25s ON memex - the heartbeat schedule #684 shipped and measured no change (48s → 57s) - pre-warming enabled on memex, degraded 7 of 16 roots, rolled back So: direct read FIRST, synced query kept only as a fallback when the direct read finds nothing. Never the other way round. #682 kept the cache primary and raced a delayed probe against it — that probe never fired once in production, and this ordering is exactly what removes the dependency on winning a race. 647/647 Graph, 8/8 Hosting.Monolith compile/pre-warm integration tests. Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
This is the actual root cause
My two earlier fixes (#681, #682) treated it one level too high, and neither worked in production: after deploying
ci.1459the uncached probe never fired (zero log lines) and the self-heal never healed — four plugin roots went to the fallback overlay again and only a scale-to-zero restored the site. Both sit on top of the layer that is actually broken.The gap
Every recovery path in
CreateExternalClientis event-driven: the change feed announces an owner restart, the latch re-subscribes. Nothing recovers a stream whose owner ACKED theSubscribeRequestand then never delivered the firstDataChangedEvent. No announce ever comes, so the latch never trips and the read just waits — in practice until the 45 s heartbeat shakes something loose.The existing comment says so outright:
The measurement
From the compile activity log's microsecond timestamps on memex:
45.20 s is one
HeartbeatIntervalto within 200 ms. 97% of every compile was a lostInitialwaiting for a heartbeat. Types then crossed the 60 s settle window and every plugin root served the "did not settle" fallback.The same silence keeps an instance's NodeType stream from ever seeing a fresh build — which is precisely why the overlay self-heal had nothing to fire on, and why only a process restart cleared it. One bug, three symptoms.
The fix
If nothing has arrived shortly after subscribing, re-send the
SubscribeRequestthrough the same provenResubscribepath. Bounded: 3 attempts, 4 s apart. A missed-wakeup nudge, not a retry loop —Take()bounds the timer, so it can never become the process-global TimerQueue root that the heartbeat comment in this same file documents (theMeshHub_IsCollectedleak).The load-bearing test is the negative one
HealthyStream_ReceivesItsData_AndNeverResubscribes— a stream that gets its snapshot must never re-subscribe. A watchdog that fires anyway re-creates async/{ClientId}hub per stream on the owner's single-threaded action block: the exact stormChangeFeedResubscribeCoalesceTestexists to prevent, and considerably worse than the bug being fixed. Plus a budget test pinning that the probe sits far below the heartbeat and the retry count stays bounded.289/289 Data tests pass.
Honest scope
This removes the 45 s stall. It does not remove the need for deploy-time precompile: a new image invalidates every assembly, so types still recompile on first activation — just in ~3 s instead of ~48 s, which is the difference between invisible and an outage.
🤖 Generated with Claude Code