Repository navigation
Make Darling's analysis budget mean something, and stop a wedged server going silent (#2430) - #2438
Conversation
…er going silent Darling had Lite's #2412 defect in the same shape. The per-server pass raced AnalyzeAsync against a Task.Delay, AnalyzeAsync received only the stopping token, and the in-flight marker was released only when the pass truly finished. So the timeout abandoned the wait without cancelling any work, and a pass that never finished left that server's marker set for the life of the service -- skipped by the guard on every later cycle, in silence, with one warning from the cycle that first timed out and then nothing ever again. It stayed invisible here for the opposite reason it was visible in Lite. DuckDB implements no async execution, so Lite's pass ran inline and a wedged read took the whole collection loop down with it. Npgsql is genuinely async and hands the thread straight back, so a wedged pass on Darling never broke anything you could see. It just stopped analysing one server. ## Why porting the Lite fix would have made things worse Arming the pass token is one line. But DarlingAnalysisService classifies its abandon arm from that token, and the question it asked was "are we shutting down?". Link the token from stoppingToken and arm it with CancelAfter, and the answer becomes yes on every ordinary overrun of a perfectly healthy service -- so each one reports itself as "abandoned at shutdown", at Information, on exactly the signal a person would use to decide the budget needs raising. That is the same class of mistake review caught on #2419's first round, and a wrong answer that reads as a calm one is worse than a loud wrong one. So the classifier moves first. IsShutdownAbandon becomes IsExpectedAbandon at the sixteen component catch sites, and the rename is the point rather than tidying: at that level the REASON does not matter, only that nobody should see nine ERRORs for work we ourselves called off, and the token those sites are handed is now a budget. Deciding WHICH abandonment is a new Classify, asked once, where both tokens are in scope -- which is why AnalysisContext now carries the stopping token separately from the token the reads observe. The old CancellationToken kept its name and lost its meaning; something had to still know what a stop is. Classify's timeout arm is deliberately narrower than its shutdown arm. A budget expiring produces exactly one shape, the token observed properly. A disposed data source or a 57P0x means the store went away, which a timeout on a running service does not cause -- so those fall through and keep the ERROR #2299 gave them. Widening the arm would have quietly relabelled that bug's only evidence for the whole window after any pass overruns, which is a thing this fix could easily have done by accident and nobody would have noticed for months. AnalysisShutdownResidueTests moves with them, as expected: it pins the call sites' argument lists, so classifier, sites and test are one change. ## The token, and how far it actually reaches The worker now links a CTS from stoppingToken, arms it with the 120s budget, and hands the pass both tokens. The sweep waits the budget plus the existing five-second unwind grace, so losing that race carries information -- the pass was asked to stop and did not -- rather than being a coin flip against its own timer. There is no Task.Run: Lite needed one because its pass ran inline, and Darling's does not. That genuinely fixes the permanent skip for most of it, because a cancelled pass throws at the next checkpoint or tokened read, the task completes, the continuation clears the marker and the server is back in the rotation. It does not fix all of it, and the measurement is worth stating plainly since the issue guessed the other way. Npgsql honours cancellation natively, but the call sites still have to hand it one, and most do not: across the analysis pipeline there are 209 async store calls and only 42 pass a token. The whole fact-collection phase -- 93 of them, and the phase that dominates a pass -- takes none. So this is 167 call sites across thirteen files, MORE than the 138 Lite deferred, not fewer. It is mechanical and it belongs in its own change, where its diff is not sitting on top of a classifier rewrite. ## Which is why the reporting is the part that closes the symptom A pass wedged inside one of those 167 reads is still wedged, and the marker still holds. What changes is that the skip stops being silent. The in-flight marker carries when the pass started and how often it has been mentioned, and a server past three times its budget is reported on a doubling backoff with how long it has been stuck and how many cycles it has cost -- loud enough to be noticed, quiet enough to stay noticed, and capped so the shift cannot run away on a service that stays up for months. A permanently-skipped server that is loudly skipped is a far smaller bug than one silently skipped: the first costs findings and says so, the second is indistinguishable from a server with nothing wrong with it. Two smaller things came with it. A pass that unwound at its budget and came back empty no longer reads as a clean all-clear -- it says it was cancelled. And the catch now releases the marker only for a pass that was never launched; it used to clear unconditionally, which got away with it only because every path that could reach it after launch had already completed the task. ## Verification Darling.Tests targets net10.0-windows and cannot run on macOS, but PerformanceMonitor.Darling.Analysis is net10.0, so the classification is testable here for real rather than pinned. Both new behavioural tests run offline in milliseconds against a data source pointed at a closed port: the token is observed before any socket work, so nothing dials it. The whole test file was compiled into a throwaway net10.0 harness with an xUnit shim and run against both branches, with the source pins reading each branch's own DarlingWorker.cs. dev 1 passed, 8 failed this branch 16 passed, 0 failed dev's one line for the failing case is the whole issue in one string: Information: [DarlingAnalysisService] Analysis abandoned at shutdown for four-args -- this pass's findings are lost by design That is an ordinary budget cancellation on a service that is not stopping. The updated AnalysisShutdownResidueTests cannot compile against dev at all, which is not a gap in the comparison -- it is the same fact from the other side, and the reason the issue said classifier, call site and test move together. dotnet build clean, 0 warnings, on the full solution with the documented macOS EnableWindowsTargeting ritual; global.json restored and not committed. ## Deliberately not in scope Threading the token into the 167 untokened store reads, measured above. Until that lands, abandonment happens between stages rather than inside a read, and the reporting is what covers the difference. analyze_now shares this pass, so it now really is cancelled at 120s instead of reporting a timeout while the work continued behind it and persisted findings anyway. The command's own answer was already TimedOut; it is true now. Fixes #2430 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
DocCommentHygieneTests caught this, which is what it is for: inserting AnalysisAbandonKind directly above `public static class AnalysisShutdown` left the class's summary sitting on top of the enum's, so the file documented the enum twice and the class not at all. XML docs take the LAST block, so tooling would have looked perfectly correct and only someone reading the file would have been misled. The enum moves above the class's doc block rather than the doc block being deleted -- the text belongs to the class and is the record of why #2299 exists. Its opening paragraph is split out while it is being touched, because the "before this" it opened with had quietly come to mean #2430 rather than #2299 once the first sentence gained a clause. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| if (findings.Count == 0 && cts.IsCancellationRequested) | ||
| { | ||
| _logger.LogWarning( | ||
| "[{Server}] Analysis exceeded {Timeout}s and was cancelled — no findings this cycle; the next cycle recomputes them", | ||
| displayName, (int)s_analysisTimeout.TotalSeconds); | ||
| return new AnalysisPassResult( | ||
| AnalysisPassStatus.TimedOut, 0, $"analysis exceeded {(int)s_analysisTimeout.TotalSeconds}s"); |
There was a problem hiding this comment.
Minor: on an ordinary budget timeout this block duplicates (and can mislabel) the classification DarlingAnalysisService.AnalyzeAsync already did.
AnalyzeAsync's catch (DarlingAnalysisService.cs:290-313) has already run AnalysisShutdown.Classify and, for the Timeout case, logged a Warning ("...was cancelled at its per-pass budget and unwound as asked...") before returning []. This block then sees findings.Count == 0 && cts.IsCancellationRequested and logs a second, differently-worded Warning ("Analysis exceeded {Timeout}s and was cancelled..."). Every scheduled per-pass-budget timeout now produces two near-duplicate WARNING lines instead of one.
Compare with the Lite twin (CollectionBackgroundService.cs): AnalysisService's inner catch logs at Info, and the outer loop's "exceeded Ns and was cancelled" is the one Warning — a deliberate two-tier severity. Darling's inner catch was upgraded to Warning for the Timeout case (DarlingAnalysisService.cs:308-311), so the outer message here is now Warning-on-Warning, which is noisier than Lite's equivalent path for the same event.
There's also an edge case this widens: Classify returns None (a genuine fault, not Timeout/Shutdown) whenever the exception isn't shaped like a cancellation even though the pass token had already fired at the time the fault landed — e.g. a query that ignored the cancellation and later threw an unrelated error after the budget expired. AnalyzeAsync correctly logs that as an ERROR with the real message and returns [], but cts.IsCancellationRequested is still true, so this block will additionally log "...exceeded Ns and was cancelled" and return AnalysisPassStatus.TimedOut — burying the real ERROR's cause behind a Warning that implies "just a timeout."
Worth considering: drop this block's own log line (and just check cts.IsCancellationRequested for the returned AnalysisPassStatus), or have AnalyzeAsync/Classify surface enough back to the caller (e.g. via AnalysisAbandonKind) that this decision isn't made twice from two different vantage points.
There was a problem hiding this comment.
Confirmed on all three points and fixed in a550675.
The double Warning is real, and the severity comparison is the right one: Lite's inner catch stays at Info so its loop's line is the single Warning, while Darling's inner catch is now correctly a Warning for the timeout case — which made mine Warning-on-Warning for one event.
The None case is the worse half and it is the one that decided the shape of the fix. A fault landing after the budget expired classifies as None, and the pass logs it as an ERROR with the real message, but findings.Count == 0 && cts.IsCancellationRequested is true anyway — so the sweep would have added "exceeded 120s and was cancelled" on top and reported TimedOut to analyze_now. That buries a genuine fault under a sentence saying the pass merely ran out of time, which is the same species of mistake as calling a timeout a shutdown, one layer further out.
Taking your second option rather than the first, because dropping only the log line would have left the status still inferred from the same two conditions. DarlingAnalysisService.EndedEarlyAs is null when the pass ran through and otherwise holds what its own catch classified, with None meaning a fault — the catch ran and the classifier said it was not an abandonment. The sweep maps that to the terminal state and adds no line of its own: Shutdown to Skipped, Timeout to TimedOut, and a fault to Error instead of TimedOut.
Pinned three ways: both behavioural tests now assert EndedEarlyAs as well as the wording, and TheSchedulerReadsThePassesOwnEnding_RatherThanInferringOne requires the read and forbids the inference it replaces.
|
Reviewed the diff (all C#, no T-SQL touched). This is a well-scoped, well-tested port of Lite's #2412 in-flight-analysis-marker fix to Darling, adapted for the fact that
One inline note on No correctness, security, or missing-index-style findings beyond that. |
…d one Review caught this and every part of it checks out. The pass classifies its own ending in one place and logs the single line for it. My sweep then looked at "no findings and the budget token has fired" and logged a second, differently worded Warning for the same event -- so an ordinary timeout produced two near-duplicate WARNINGs where the Lite twin produces one, since Lite's inner catch stays at Info and Darling's now correctly does not. The worse half is the case those two conditions cannot tell apart. A fault that lands AFTER the budget expired classifies as None, and the pass logs it as an ERROR with the real message -- but the token has fired and the result is empty, so the sweep would have added "exceeded 120s and was cancelled" on top and reported it to analyze_now as TimedOut. That buries a genuine fault under a sentence saying the pass merely ran out of time, which is the same species of mistake as classifying a timeout as a shutdown, one layer further out. So the ending is carried out of the pass rather than re-derived. EndedEarlyAs is null when the pass ran through and otherwise holds what its own catch classified, where None means a fault -- the catch ran and the classifier said it was not an abandonment. The sweep now maps that to the terminal state analyze_now reports and adds no line of its own: shutdown to Skipped, budget to TimedOut, and a fault to Error rather than to TimedOut. The two behavioural tests assert the property as well as the wording, and a new source pin requires the sweep to read EndedEarlyAs and forbids the inference it replaces. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
Reviewed. This PR is C#/.NET (Darling worker + analysis service), so the T-SQL style rules in CONTRIBUTING.md don't apply — no I traced through the core logic in detail rather than just skimming:
Nothing to flag on security (no new input handling, no query construction, no secrets/process/network surface changed beyond the existing Npgsql calls) or performance (the extra One very minor, pre-existing (not introduced here) rough edge for awareness rather than action: |
146 store calls across the fact collector and the drill-down collector took the no-argument overload, which is why erikdarlingdata#2438's budget could abandon a pass between stages but never inside a read. A wedged query held its connection until it finished on its own, and the service that had already given up on that server sat there holding a session it was no longer waiting for. Threading the reads alone would have accomplished almost nothing, and that is the part worth reading twice. The fact collector's per-query catches are bare `catch { }` on purpose -- a missing table degrades to "no facts", never an exception -- so a fired token would have been caught thirty times over and the pass would have carried on to the next collector each time, dialling the store again to be told again. The measured proof is in the behavioural test: reverted, it fails with an NpgsqlException instead of an OperationCanceledException, which is the collector connecting to the store while holding a token that had already been cancelled before the call. So all 27 of those catches now carry the classification the rest of the pass has used since erikdarlingdata#2299 -- `when (!AnalysisShutdown.IsExpectedAbandon(ex, ...))` -- and an abandonment propagates to the single line the pass logs for it instead of being swallowed per-metric. The catch bodies and their comments are unchanged; the only thing that stops being caught is the one thing we asked for. Four collect methods have no catch at all and never did: their reads propagate straight up, which is the same outcome by a shorter route. AppendDmvSnapshotRowsAsync takes a required token rather than a defaulted one for the reason the plan fetcher did: three callers share it, two are on the pass, and a default would have let either keep passing nothing silently. The viewer is the third and it genuinely has no pass to abandon -- it says so at its own call site rather than in the shared method, because the exception belongs to the caller. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
1 participant
Closes #2430.
Darling had Lite's #2412 defect in the same shape. The per-server pass raced
AnalyzeAsyncagainst aTask.Delay,AnalyzeAsyncreceived only the stopping token, and the in-flight marker was released only when the pass truly finished. So the timeout abandoned the wait without cancelling any work, and a pass that never finished left that server's marker set for the life of the service — skipped by the guard on every later cycle, in silence, with one warning from the cycle that first timed out and then nothing ever again.It stayed invisible here for the opposite reason it was visible in Lite. DuckDB implements no async execution, so Lite's pass ran inline and a wedged read took the whole collection loop down with it. Npgsql is genuinely async and hands the thread straight back, so a wedged pass on Darling never broke anything you could see. It just stopped analysing one server.
Why porting the Lite fix would have made things worse
Arming the pass token is one line. But
DarlingAnalysisServiceclassifies its abandon arm from that token, and the question it asked was "are we shutting down?". Link the token fromstoppingTokenand arm it withCancelAfter, and the answer becomes yes on every ordinary overrun of a perfectly healthy service — so each one reports itself as "abandoned at shutdown", at Information, on exactly the signal a person would use to decide the budget needs raising. Same class of mistake review caught on #2419's first round, and a wrong answer that reads as a calm one is worse than a loud wrong one.So the classifier moved first.
IsShutdownAbandonbecomesIsExpectedAbandonat the sixteen component catch sites, and the rename is the point rather than tidying: at that level the reason does not matter, only that nobody should see nine ERRORs for work we ourselves called off — and the token those sites are handed is now a budget. Deciding which abandonment is a newClassify, asked once, where both tokens are in scope. That is whyAnalysisContextnow carries the stopping token separately from the token the reads observe: the oldCancellationTokenkept its name and lost its meaning, and something had to still know what a stop is.Classify's timeout arm is deliberately narrower than its shutdown arm. A budget expiring produces exactly one shape — the token observed properly. A disposed data source or a 57P0x means the store went away, which a timeout on a running service does not cause, so those fall through and keep the ERROR #2299 gave them. Widening the arm would have quietly relabelled that bug's only evidence for the whole window after any pass overruns, which is a thing this fix could easily have done by accident.AnalysisShutdownResidueTestsmoves with them, exactly as the issue predicted: it pins the call sites' argument lists, so classifier, sites and test are one change.The token, and how far it actually reaches
The worker links a CTS from
stoppingToken, arms it with the 120s budget, and hands the pass both tokens. The sweep then waits the budget plus the existing five-second unwind grace, so losing that race carries information — the pass was asked to stop and did not — rather than being a coin flip against its own timer. There is noTask.Run: Lite needed one because its pass ran inline, and Darling's does not.That genuinely fixes the permanent skip for most of it. A cancelled pass throws at the next checkpoint or tokened read, the task completes, the continuation clears the marker, and the server is back in the rotation.
It does not fix all of it, and the measurement runs the other way from the issue's guess. Npgsql honours cancellation natively, but the call sites still have to hand it one, and most do not:
PgFactCollector.*(the phase that dominates a pass)PgDrillDownCollector.*PgAnomalyDetectorPgFindingStoreSo threading the token in is 167 call sites across thirteen files — more than the 138 Lite deferred, not fewer. It is mechanical, and it belongs in its own change rather than sitting on top of a classifier rewrite.
Which is why the reporting is what closes the symptom
A pass wedged inside one of those 167 reads is still wedged and the marker still holds. What changes is that the skip stops being silent. The in-flight marker now carries when the pass started and how often it has been mentioned, and a server past three times its budget is reported on a doubling backoff with how long it has been stuck and how many cycles it has cost — capped so the shift cannot run away on a service that stays up for months. A permanently-skipped server that is loudly skipped is a far smaller bug than one silently skipped: the first costs findings and says so, the second is indistinguishable from a server with nothing wrong with it.
Two smaller things came with it. A pass that ended early no longer reads as a clean all-clear: the scheduler reads
DarlingAnalysisService.EndedEarlyAs— what the pass's own catch classified — and turns it into the terminal stateanalyze_nowreports, adding no second log line of its own. That shape came out of review: inferring it here from "no findings and the budget token has fired" produced a duplicate Warning for every ordinary timeout, and, worse, said the same thing about a genuine fault that landed after the budget expired — burying its ERROR under a sentence claiming the pass merely ran out of time. A fault now reportsError, notTimedOut.And the catch releases the marker only for a pass that was never launched; it used to clear unconditionally, which got away with it only because every path reaching it after launch had already completed the task.
Verification
Darling.Teststargetsnet10.0-windowsand cannot run on macOS, butPerformanceMonitor.Darling.Analysisisnet10.0— so the classification is testable here for real rather than pinned. Both behavioural tests run offline in milliseconds against a data source pointed at a closed port: the token is observed before any socket work, so nothing ever dials it.The whole test file was compiled into a throwaway
net10.0harness with an xUnit shim and run against both branches, with the source pins reading each branch's ownDarlingWorker.cs.DarlingAnalysisBudgetTests+DarlingWedgedServerReportingTests(+ residue tests)dev's line for the failing case is the whole issue in one string:
That is an ordinary budget cancellation on a service that is not stopping.
The updated
AnalysisShutdownResidueTestscannot compile against dev at all, which is not a gap in the comparison — it is the same fact from the other side, and the reason the issue said classifier, call site and test move together. (dev needed two compile-only shims for the behavioural file: an inertAnalysisContext.ShutdownTokenand an ignored fifthAnalyzeAsyncparameter. Neither is read by dev, which is precisely the state under test.)dotnet buildclean on the full solution with the documented macOSEnableWindowsTargetingritual;global.jsonrestored and not committed. The eightxUnit2031warnings inDarlingFirewallCheckTests.csare already ondevand are not from this branch.Deliberately not in scope
analyze_nowshares this pass, so it now really is cancelled at 120s instead of reporting a timeout while the work continued behind it and persisted findings anyway. The command's own answer was alreadyTimedOut; it is true now.