Startup Query Store repair logs its progress lines before it returns (#5693)

[erikdarlingdata]

Fixes #5693.

Why

QueryStoreSliceRepairService.RepairOnStartupAsync passed new Progress<string>(...) to RepairAsync. Progress<T> does not run its handler inline: it posts each report to the captured synchronization context, or to the thread pool when there is none. The repair runs from a background task, so the "#1912" progress lines were logged late, on pool threads, and could land after the repair returned and out of order with the warnings logged inline. With a test logger that writes to a plain List, a late line can arrive while a test reads the list; that is how Rewrite_WithTooLittleFreeDisk_SkipsTheFile_AndSaysWhy failed once in CI with "Collection was modified".

What changes

• Lite/Services/QueryStoreSliceRepairService.cs: a small private InlineLogProgress : IProgress<string> logs each line on the calling thread, before Report returns. The startup repair uses it instead of Progress<string>.
• Lite.Tests/SliceRepairStartupTests.cs:
  • New test StartupRepair_LogsItsProgressLines_BeforeItReturns. It runs the repair under a synchronization context that forwards to the thread pool and counts posts made by a Progress<T>. It asserts zero such posts, that the archive and views progress lines are in the log when the call returns and in order, and that the log count does not change after a 250 ms wait. It does not depend on timing.
  • CapturingLogger now owns its list, adds under a lock, and exposes Entries as a snapshot taken under the same lock (plus Clear()). Existing tests read log.Entries.

Other Progress<T> users

Searched Lite/ for Progress<, new Progress( and : IProgress<: the only new Progress<...> is the one fixed here. No existing IProgress<> implementation to reuse. No other service logs through Progress<T> from a background task, so there is nothing else to change.

RED line

Old code, new test: Assert.Equal() Failure: Values differ / Expected: 0 / Actual: 2 (two Progress<T> posts). An earlier version of the test that only checked for the lines in the log passed on the old code in one run, because the pool delivered them in time, so the test counts the posts instead.

Test plan

• Lite and Lite.Tests build: 0 Warning(s), 0 Error(s)
• -class "*SliceRepairStartupTests*": Total: 14, Errors: 0, Failed: 0
• -class "*Census*": Total: 67, Errors: 0, Failed: 0
• -trait Stage=Guard: Total: 493, Errors: 0, Failed: 0
• Full suite: left to CI

Changelog

SECTION: Fixed
ENTRY:

• Startup Query Store repair now logs its progress lines in order, before it returns ([Startup Query Store repair logs its progress lines before it returns (#5693) #5694]) - the Information progress lines of the one-time startup repair were logged late from a pool thread and could appear after the repair's result or out of order with its warnings. They are now written inline, in order, before the repair returns.

[claude]

Non-blocking, and it does not bite today — but the finally restores the context on whichever thread resumes the await, not the thread the try set it on. If anything inside RepairOnStartupAsync ever yields, the continuation goes through ProgressPostCountingContext.Post onto a pool thread, the restore lands there, and the counting context stays installed on the xunit worker thread for the rest of the run. The Post handler leaks the same way in the other direction: it calls SetSynchronizationContext(this) at line 178 and never clears it, so every pool thread it touches keeps the context after d(state) returns.

Why it is inert as written: nothing in the repair path yields. There is no Task.Delay/Task.Run/Task.Yield anywhere in QueryStoreSliceRepairService, AcquireReadLock is a blocking call, and DuckDB.NET's async completes synchronously — which is exactly the premise DuckDbInitializer.cs:342 records and DuckDbLockModelTests.DuckDbAsyncStillCompletesOnTheCallingThread guards. So with the fixed code the context receives zero posts and the restore happens on the setting thread.

That ties the hygiene of this test to that premise: the day the tripwire goes red, this test starts leaving a SynchronizationContext on threads it does not own (and, separately, resumes a thread-affine ReaderWriterLockSlim hold on another thread). A try { d(state); } finally { SetSynchronizationContext(null); } in the work item, and restoring the test's context from a known thread, would make it independent of it.

[claude]

Non-blocking observation about what this pin will fail on in two years' time. The discriminator is that Progress<T> posts an instance-bound SendOrPostCallback (_invokeHandlers = new SendOrPostCallback(InvokeHandlers)), so d.Target is the Progress<T>. That is an implementation detail of the BCL, not a contract: if it ever becomes a static callback carrying the instance in state, owner is a closure/null, the counter stays 0, and the pin passes for a reason that has nothing to do with the fix — and because the fixed code posts nothing at all, vacuous reads exactly like green here.

The sentence in the doc comment ("the old code posts at least one, the inline reporter posts none") is the stronger property and it holds for any post: against the fixed code the context receives no posts whatsoever on this path. Counting every post and asserting 0 would survive a BCL change, at the cost of coupling the test to DuckDB.NET's synchronous completion (see the other comment). Either way it is worth a line here saying which detail the 0 depends on, so a future reader who sees it go vacuous knows where to look.

[claude]

Verdict: LGTM

Claims

• VERIFIED — RepairOnStartupAsync passed new Progress<string>(...) to RepairAsync — the removed line in the Lite/Services/QueryStoreSliceRepairService.cs:413 hunk.
• VERIFIED — the repair runs from a background task — Lite/MainWindow.xaml.cs:266, _ = Task.Run(() => sliceRepair.RepairOnStartupAsync(_backgroundCts.Token)), un-awaited.
• VERIFIED — a private InlineLogProgress : IProgress<string> logs each line on the calling thread before Report returns, and the startup repair uses it instead of Progress<string> — QueryStoreSliceRepairService.cs:1251-1253, constructed at :414.
• VERIFIED — the new test asserts zero Progress<T> posts, the archive and views lines present and in that order, and an unchanged log count after a 250 ms wait — Lite.Tests/SliceRepairStartupTests.cs:147, :152-154, :156-158; the two lines it looks for are the Report sites at QueryStoreSliceRepairService.cs:1051 and :771.
• VERIFIED — CapturingLogger now owns its list, adds under a lock, exposes Entries as a snapshot taken under the same lock, gains Clear(), and every existing reader was moved to log.Entries — SliceRepairStartupTests.cs:538-556, readers at :203, :263, :269, :299, :383-384. No other file references this nested type: every other CapturingLogger in Lite.Tests/Darling.Tests is its own private nested class, so the constructor change cannot break a caller.
• VERIFIED — the only new Progress<...> is the one fixed, there is no IProgress<> implementation to reuse, and no other service logs through Progress<T> — a repo-wide grep for IProgress< / Progress< returns only deprecated/Installer.Core/{DependencyInstaller,InstallationService}.cs (deprecated tree, IProgress<InstallationProgress>, not a logging adapter) and this file.
• VERIFIED — "it does not depend on timing", for the assertion that carries the red: :147 counts inside Post, synchronously, and every Report happens before RepairAsync returns; the 250 ms wait at :157 can only false-green, never false-red, because nothing in the fixed path can log after the awaited call returns.
• UNVERIFIED — Progress<T> posts each report to the captured synchronization context, or to the thread pool when there is none — documented BCL behaviour, not a fact in this tree; it is the mechanism the new context's counter exploits and the reason the old code's two reports were posts.
• UNVERIFIED — Rewrite_WithTooLittleFreeDisk_SkipsTheFile_AndSaysWhy failed once in CI with "Collection was modified" — needs that run's log. The mechanism is consistent with the pre-change code: the sink was a bare List (new CapturingLogger(log)) appended from a pool thread while Assert.Contains(log, …) enumerated it.
• UNVERIFIED — RED line "old code, new test: Expected: 0 / Actual: 2" — needs a run against the pre-change service. The number corroborates: exactly two Report calls are reachable for this fixture (:1051 per-file, :771 views), while the hot-store line at :724 cannot fire because the fixture's hot table carries no split groups.
• UNVERIFIED — test plan (0 Warning(s)/0 Error(s); *SliceRepairStartupTests* 14/0/0, *Census* 67/0/0, Stage=Guard 493/0/0) — needs a build and a Windows test host.

Riskiest lines

1. Lite/Services/QueryStoreSliceRepairService.cs:414 — the reporter swap itself: every #1912 progress line in the startup repair now goes through it, and it is the only production caller that passes a progress (RepairAsync's other callers are tests, which pass none) — pinned by StartupRepair_LogsItsProgressLines_BeforeItReturns.
2. Lite/Services/QueryStoreSliceRepairService.cs:724 — the one Report site that sits inside the DuckDB write lock (:653-:725), so this line is the one the change moves onto the lock-holding thread. Checked and benign: Lite's ILogger is AppLoggerAdapter (MainWindow.xaml.cs:252), whose Log ends at AppLogger.Log → s_buffer.Enqueue (Lite/Services/AppLogger.cs:318-321) with the file write on a 5 s timer, so there is no file I/O and no re-entry into s_dbLock under the write lock — UNPINNED (no test asserts the logger stays non-blocking).
3. Lite.Tests/SliceRepairStartupTests.cs:137-145 and :176-181 — a SynchronizationContext installed on an xunit worker thread, restored in a finally that runs on whichever thread resumes the await, with a Post handler that installs itself on pool threads and never clears it — UNPINNED; inert only while no await in the repair path yields (see the inline comment).

Traps near this diff

• "Lite and Darling ship in parity (CONTRIBUTING's two-store rule): a fix to one SKU's reader, tool, alert or description without the counterpart's is a finding, not a nit" — does not apply: QueryStoreSliceRepairService is Lite-only (DuckDB hot table plus parquet archive, Lite/Services/QueryStoreSliceRepairService.cs:43), and the repo-wide IProgress< grep above shows Darling has no Progress<T> logging adapter to fix in step.
• "A test that reads the clock twice measures the CI scheduler: the delta-seeder tests failed at 123 and 243 on unrelated PRs (#3676). One anchor owns both ends of an interval." — does not apply: the new test reads no clock. Its only wall-clock element is the 250 ms wait at SliceRepairStartupTests.cs:157, which can only false-green; the red comes from the synchronous post count at :147.
• "A pin that encodes the lie: ACappedResult_WithholdsTheUnsatisfiedSummary_… handed the builder two facets at limit = 2 and asserted truncated — the >= limit inference as its own proof. Ask what a pin would fail ON." — does not apply: the pin fails on a Progress<T> post (:147) and on a missing or out-of-order line (:152-154), neither of which is the inference the production code makes. The one way it could go quietly vacuous is a BCL change to Progress<T>'s callback shape — flagged inline, non-blocking.
• "An expression-bodied member holding a { } property pattern is read SHORT by the T-SQL convention guard's member walk (#3667; the #3607 precedent) — a member the walk cannot read whole is one no census can see into." — does not apply: the guard scans all of Lite/ (Darling/Darling.Tests/TsqlConventionGuardTests.cs:74-93), and this diff adds one expression-bodied member there (InlineLogProgress.Report, :1253) — but it carries no string literal at all, so nothing can escape EveryTsqlLiteralInTheCorpus_IsAttributedToADeclaredMember. The { IsGenericType: true } property pattern is in Lite.Tests/SliceRepairStartupTests.cs:171, outside the scanned trees (TsqlConventionGuardTests.cs:1434).

Divergence (blind read vs PR body)

One omission, not a defect. The body's account is "the lines are logged inline instead of posted", and it does not mention that one of the four Report sites — QueryStoreSliceRepairService.cs:724, the hot-store line — sits inside the DuckDB write lock, so that line's logging moves from a pool thread onto the lock-holding thread. I chased it because a sink that blocked or re-entered s_dbLock there would be a LockRecursionException on a NoRecursion ReaderWriterLockSlim: it does neither (AppLogger.Log only enqueues, AppLogger.cs:318-321), so the change is safe, but it is a behaviour the body leaves out. Everything else matches: the mechanism, the single new Progress<...> census, the CapturingLogger refactor and its call-site sweep, and the shape of the new test all read as described. The "Actual: 2" in the RED line matches the two reachable Report sites for this fixture, which is corroboration rather than confirmation.

Reviewer checklist

• Run the full Lite.Tests suite on Windows (not just -class "*SliceRepairStartupTests*"), and ideally twice: the new test installs a SynchronizationContext on an xunit worker thread, and whether any residue escapes onto pool threads is not observable from a read-only tree.
• Confirm the pin red-first against the pre-change service and that the failure is the post count (Expected: 0 / Actual: 2), not the ordering assertion — the ordering half passed on the old code in one run by the author's own account.
• On a real pre-#1907 store, read lite_YYYYMMDD.log after a startup repair and confirm the #1912 progress lines are interleaved in order with the repair's warnings and precede the "repair complete" line.