[TEST FLAKE] Two live-store tests fail on unrelated diffs and pass on re-run (scale-test noise floor, and a database-state heal race)

[erikdarlingdata]

Two tests failed today on PRs whose diffs cannot reach them, and both passed on a re-run of the same commit. Filing rather than leaving them as re-run folklore.

1. StoreSelfMetricsTests.ScaleTest_JobDurationGrowsWithVolume_TelemetryRecordsIt_AndTheAlertFires_AgainstDevPostgres

10x volume did not run longer than 1x (d1=970ms, d10=863ms) — job runtime is not scaling
with volume, which invalidates the #2136 capacity model.

StoreSelfMetricsTests.cs:404. Failed on #2265, whose diff is the Azure sweep predicate plus two new test files.

Root cause is in the assertion, not the product. It compares two sub-second durations on a shared CI runner and requires the larger volume to be strictly slower. At ~900 ms the run-to-run noise exceeds the signal it is trying to measure — 1× happened to land 107 ms slower than 10×. The capacity model it guards is real; the measurement just has no margin.

Worth considering: require a ratio rather than an inequality (e.g. d10 > d1 * 1.5), scale the volumes until the difference clears the noise floor, or take a best-of-N. As written it will keep failing at a low rate forever, and each failure costs a re-run and a moment of "is that mine?".

2. DatabaseStateExpectedStoreTests.RebaselinedByHandDuringAnOutage_HealsOnceTheDatabaseRecovers

Assert.Empty() Failure: Collection was not empty
Collection: [DatabaseStateInfo { DatabaseName = "Payments", ExpectedState = "SUSPECT",
             LastAlertedState = "", StateDesc = "ONLINE" }]

Lite.Tests/DatabaseStateExpectedStoreTests.cs:342. Failed on the same PR one commit later — a commit that deleted an unused method and rewrote two doc summaries, so it cannot reach this test either. Passed on re-run.

I did not get to a root cause on this one. The expected state was still SUSPECT when the test expected it cleared, which reads like an ordering or visibility issue in the store rather than noise, so it may be a genuine race worth someone looking at properly rather than a timing tolerance.

Why file it

Both cost a re-run today, and #2223 is already open for a third flake in the same suite family. A re-run that goes green teaches nothing durable, and the next person to see either failure will spend the same few minutes deciding whether it is theirs. Two of these in one afternoon on unrelated diffs is also the point at which the pattern matters more than the individual tests.

[erikdarlingdata]

Analysis on item 1, and a reason I am not pushing a tolerance change for it.

The assertion carries its own justification:

/* 1. The capacity claim itself: more volume, longer run. Monotonicity, not a ratio — runner jitter owns the constant factor, the direction is ours. */

That reasoning is inverted. Monotonicity is the assertion jitter breaks most easily, because it has zero margin: it fails whenever noise exceeds the true difference, however small that difference is. A ratio is what survives jitter, since it demands the signal clear a stated multiple. The comment argues for the weaker form on the grounds that protect the stronger one.

The observed pair says the margin is genuinely thin: d1=970ms, d10=863ms for a 10× volume increase. So either the noise is ≥ ~110 ms at these durations, or the variable component at 50k → 500k rows is small next to fixed overhead — most plausibly both, since ~900 ms of largely-constant cost with a small variable part is exactly what produces an occasional inversion.

Why I am stopping here rather than changing it. Every candidate fix needs a number I cannot measure on this machine: a ratio threshold needs the true scaling factor, more volume separation needs to know how much makes the variable part dominate, and best-of-N needs the jitter distribution. Both test projects are net10.0-windows and this one needs a live Postgres, so I cannot take any of those measurements. Guessing a threshold for an intermittent test is how it looks fixed — the same reason #2223's earlier attempt was correctly put down rather than guessed at.

What I would suggest for whoever has a rig: run the existing test ~20 times unchanged and record the (d1, d10) pairs. That gives the jitter distribution and the true scaling factor in one go, and then the choice between "raise the volume separation" and "assert a ratio" is a decision rather than a guess. If the pairs show scaling is genuinely marginal at these volumes, the honest fix is more separation, because the #2136 capacity claim deserves a test that can actually see it.

#2223 is now fixed (#2267) — different root cause than that issue suspected, found from source: the tests seeded nine days of history while arming a seven-day retention policy, so they armed a policy that would delete their own fixture. Item 2 here (the DatabaseStateExpectedStoreTests heal) I still have not root-caused, and still think reads more like a real race than noise.

[erikdarlingdata]

Root-caused item 2 from source. It is not a store race, and it is not noise — the product is behaving exactly as designed. The test is assuming something the design explicitly does not promise.

The mechanism

LocalDataService.GetDatabaseStateDeviationsAsync runs its four maintenance statements — seed, the #2189 heal, the #2203 forget, and the prune — inside a best-effort block:

try
{
    using var maintenance = await OpenWriteConnectionAsync();   // AcquireWriteLock(timeout: 5s)
    ... seed ... heal ... forget ... prune ...
}
catch (TimeoutException)
{
    /* Archival or compaction holds the write lock. Skip this cycle's maintenance and read anyway */
}

using var connection = await OpenConnectionAsync();   // the deviation read runs REGARDLESS

OpenWriteConnectionAsync is AcquireWriteLock(timeout: TimeSpan.FromSeconds(5)), and that lock is static — shared by the whole process. The method's own comment says so, and says how it was discovered:

That is how this surfaced — an unrelated server-tags test timed out acquiring the write lock while this method held the read lock, on a static lock shared by the whole process.

Lite.Tests runs test classes in parallel, all against that one process-wide lock. So when another class holds the write lock long enough, this call's acquisition times out, the heal is skipped, and the deviation read still runs.

That produces the reported row exactly

DatabaseStateInfo { DatabaseName = "Payments", ExpectedState = "SUSPECT", StateDesc = "ONLINE" }

• ExpectedState = SUSPECT — the heal never ran, so the poisoned baseline is still there
• StateDesc = ONLINE — the read ran fine and saw the recovered snapshot

Both halves at once are only reachable by skipping maintenance while completing the read, which is precisely what the catch (TimeoutException) arm does. And it's intermittent for the right reason: it depends on what another class was doing in that 5-second window, which is why it tracks parallel load rather than the diff.

I'd ruled out the obvious alternatives first — the fixture mints a unique temp dir per instance (Guid.NewGuid()), so no cross-class file sharing, and ServerId 7788 is used by no other class. So the contamination vector is the process-wide lock, not the store.

Fixing the test

The test asserts a best-effort side effect, which under contention is by definition not guaranteed. Three options, roughly in order of how much I like them:

1. Make the dependency explicit — have the test invoke the maintenance step directly (or retry GetDatabaseStateDeviationsAsync until the expectation heals, with a bounded number of attempts), so a lock-contended cycle retries instead of asserting a stale read.
2. Put the write-lock-dependent classes in one xunit collection so they don't run parallel to each other. Cheapest, but it slows the suite and only reduces the odds — anything else in the process can still hold the lock.
3. Raise the 5s timeout in tests. I'd avoid this; it's tuning a number to make a race less likely rather than removing the dependency.

The product finding underneath it

catch (TimeoutException) logs nothing. Skipping is the right behaviour — the block comment makes a good case that it's the only lossless option — but it is currently completely silent, so in production a sustained period of write-lock contention means baselines quietly stop being seeded and healed with no evidence anywhere that a cycle was skipped. Given #2189's whole point is that an unhealed baseline "inverts the alert permanently," a skipped heal is worth knowing about.

I'd suggest a log on the transition into and out of skipping (the shape #2255 just used for the DPAPI failure: full text once per state change, not once per cycle) rather than a line per sweep, since under real contention this could fire every cycle. Happy to do that — flagging rather than bundling it, since the swallow is deliberate and how loud it should be is your call.

Item 1 is unchanged: still needs the (d1, d10) distribution from a rig before any threshold choice, for the reasons in my earlier comment. I'd rather leave it flaky than guess a number and have it look fixed.

[erikdarlingdata]

New datum on item 1, and it reframes the mechanism — this is not jitter.

It failed again today on #2285, whose diff is one service file plus one new test file and cannot reach it. The numbers:

10x volume did not run longer than 1x (d1=689ms, d10=689ms)

Byte-identical. Both readings 689ms. My earlier analysis reasoned from the first observed pair (d1=970ms, d10=863ms) and concluded the variable component was thin against runner noise — which is a reasonable read of two different numbers 107ms apart. It is not a reasonable read of the same number twice. Two independent sub-second timings of different workloads do not land on the same millisecond by chance.

So I withdraw the framing that this needs a jitter distribution before it can be fixed. That was measuring the wrong thing.

What identical durations actually implicate

RunJobViaSchedulerAsync is sound on the question I would have suspected first — it polls last_successful_finish and waits for it to advance, so each read is of a genuinely new completed run, not a stale row. That rules out the obvious explanation.

What is left is that both runs did the same amount of work, which on this test means close to none: the duration is dominated by fixed per-run overhead and the compression policy is not actually compressing the seeded rows in the way the test assumes. The 1x pass seeds daysBack: 10 and the 10x pass seeds daysBack: 8, each expecting its own chunk to become eligible and be compressed — if neither is eligible, or if the work is bounded by something other than row count, you get two runs of identical fixed cost and an assertion that can only fail by coincidence when it passes.

That is a testable claim and it does not need a rig. The next step is to make the test report what the job did, not just how long it took — rows compressed, chunks compressed, last_run_status — for both passes. If the answer is "zero chunks, twice", the monotonicity assertion has never been measuring the #2136 capacity model at all, and the fix is to make the volumes genuinely produce compressible chunks rather than to loosen a threshold.

I have not made that change yet — it is a real investigation rather than a tolerance tweak, and I would rather land it with the diagnostic than guess a second time. Recording the datum now because it is the piece that was missing, and because "identical" is a much sharper clue than "close".

Item 2 remains fixed (#2275, plus the skipped-maintenance logging in #2281).