Repository navigation
Give every alert-pass read an explicit command deadline (Part of #2874) - #2882
Conversation
All forty-nine commands across the seven alert-pass types set no CommandTimeout, so every one inherited Npgsql's undocumented 30s default. On 2026-09-04 the forced-plan read failed five times on the production store, each surfacing as "Exception while reading from stream" — how Npgsql renders its own deadline, and the misdiagnosis #2826 exists to prevent. Unlike #2810 and #2871, which sit under DarlingWorker.s_analysisTimeout's 120s CancelAfter, this pass has NO enclosing budget: EvaluateAlertsAsync is called with the plain stopping token, so the per-command deadline is the pass budget multiplied by the number of sequential reads — 49 x 30s of exposure while the body holds one of only four fleet sweep permits and that server's relaunch is skipped throughout. The value is therefore the first in this family set BELOW what it inherited. 10s is bounded under by the measured worst case (shipped queries timed on the production store's three busiest servers: the forced-plan check at 1,744.9ms cold over ~6.0GB dominates; every other read lands under 3ms) and bounded over by the 30s s_alertSweepInterval the pass runs on. The asymmetry justifies erring short — an exceeded deadline skips one alert check and retries 30s later, while a long-running read starves fleet-wide collection. Every observed failure was killed AT the 30s ceiling, so the record is right-censored: 10s is chosen from the measured cost and the cadence, not fitted to a distribution the data cannot show. Pinned structurally over BOTH construction shapes. #2874's census counted only `new NpgsqlCommand(`, missing NpgsqlDataSource.CreateCommand(sql) — the same inherited default, and four of this group's own sites. The pin scans by statement rather than a line window, because these sites embed verbatim SQL and a window wide enough to reach the initializer would read the NEXT command's deadline and report an untimed site clean. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MX6HyjsuDCs15qGB2rh4Gy
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| replica_role, parameter_sensitivity_cofired, outcome, detail, related_action_id) | ||
| VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18) | ||
| RETURNING action_id", connection); | ||
| RETURNING action_id", connection) { CommandTimeout = DarlingAlertReadAdapter.AlertPassCommandTimeoutSeconds }; |
There was a problem hiding this comment.
Minor scope note: PgPlanForceActionStore isn't actually reachable from EvaluateAlertsAsync — grepping its callers, the only one is PlanForceBot.RunAfterAnalysisAsync (wired in via RunScheduledAnalysisAsync, DarlingWorker.cs:4081), which runs after the AN3 analysis pass's own passCts/120s budget has already completed, on the plain stoppingToken. So this store's 4 sites don't belong to "the alert evaluation pass" the PR body and AlertPassCommandTimeoutSeconds's doc comment describe (30s sweep cadence, MaxConcurrentServerSweeps fleet permits, etc.) — they belong to the post-analysis force-plan pass, which happens to have a similar "no enclosing budget" shape but for different reasons (different cadence, different permit).
Tightening the timeout here is still reasonable (10s < the previous 30s default either way), but the constant name and its justification are borrowed from a pass this store doesn't run in. Worth either renaming to something pass-agnostic (e.g. UnbudgetedReadCommandTimeoutSeconds) or documenting PlanForceBot's own budget shape separately, so the next reader doesn't assume this store shares the alert pass's 30s-cadence bound.
There was a problem hiding this comment.
Correct, and verified rather than taken on trust: PgPlanForceActionStore's only caller is PlanForceBot, and the hook is constructed at DarlingWorker.cs:4084 closing over the plain stoppingToken — so although it is invoked lexically inside the try that owns passCts, it runs outside that 120s CancelAfter's cancellation. Unreachable from EvaluateAlertsAsync.
I took the third option rather than either you offered: dropped those 4 sites from this PR. Renaming to something pass-agnostic would have kept the value while quietly widening the claim — the two passes share the unbudgeted shape but not the cadence, and my upper bound is derived specifically from the 30s s_alertSweepInterval. A pass-agnostic name would have made that bound look general when it is not.
Doing them properly needs their own measurement and their own cadence reasoning (analysis interval, clamped 5-360 min), which this PR has not done. They are left for their own group on #2874, and the exclusion is now documented in both the constant and the pin's file list — specifically so the next reader does not re-add them by resemblance, which is exactly what I did.
Group is now 45 sites across 6 types. Pin re-verified against the real build: 45 sites, 0 offenders.
ReviewVerified the mechanical claim first: grepped the 7 listed files for Correctness gap: one site in the exact same pass was missed, and it's invisible to the new pin
var (sqlCpu, totalCpu) = await ReadLatestCpuAsync(runtime.ServerId, cancellationToken);
using var command = new NpgsqlCommand(@"
SELECT sqlserver_cpu_utilization, other_process_cpu_utilization
FROM cpu_utilization_stats
WHERE server_id = $1
ORDER BY sample_time DESC
LIMIT 1", connection);This is the same inherited-30s-default mechanism the PR fixes everywhere else, on a read that runs inside the identical unbudgeted, fleet-permit-holding pass the PR's own reasoning is built around -- it just lives in Minor: scope of PgPlanForceActionStoreLeft as an inline comment -- that store's 4 sites are actually called from No SQL injection / secrets / process concerns -- all parameterized, no new external I/O. No Lite/Darling parity issue beyond the note above. |
Review catch, and correct. PgPlanForceActionStore is not reachable from EvaluateAlertsAsync at all — its only caller is PlanForceBot.RunAfterAnalysisAsync, dispatched as the analysis pass's post-pass hook. Verified: the hook is constructed at DarlingWorker.cs:4084 closing over the plain stoppingToken, so although it is invoked lexically inside the try that owns passCts, it runs outside that 120s CancelAfter's cancellation. It therefore shares the unbudgeted shape but NOT the cadence: it runs on the analysis interval (clamped 5-360 minutes), not this pass's 30s s_alertSweepInterval. The upper bound in AlertPassCommandTimeoutSeconds is derived from that 30s cadence, so applying it to those four sites would have attached a justification borrowed from a pass they do not run in. Dropping them rather than renaming the constant: they need their own measurement and their own cadence reasoning, which this PR has not done. Left for their own group on #2874, and the exclusion is documented in both the constant and the pin so the next reader does not re-add them by resemblance. Group is now 45 sites across 6 types. Pin re-verified: 45 sites, 0 offenders. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MX6HyjsuDCs15qGB2rh4Gy
# Conflicts: # CHANGELOG.md
|
Reviewed. This is a narrow, mechanical change (Darling-only, C#) and it holds up:
No correctness, security, or performance issues found. Nothing to flag inline. |
# Conflicts: # CHANGELOG.md
| private static string StatementSpanFrom(string text, int start, int statements) | ||
| { | ||
| var depth = 0; | ||
| var seen = 0; | ||
| var i = start; | ||
|
|
||
| while (i < text.Length) | ||
| { | ||
| var c = text[i]; | ||
|
|
||
| if (c == '@' && i + 1 < text.Length && text[i + 1] == '"') | ||
| { | ||
| i = SkipVerbatimString(text, i + 2); | ||
| continue; | ||
| } | ||
|
|
||
| if (c == '"') | ||
| { | ||
| i = SkipRegularString(text, i + 1); | ||
| continue; | ||
| } | ||
|
|
||
| if (c is '(' or '[' or '{') | ||
| { | ||
| depth++; | ||
| } | ||
| else if (c is ')' or ']' or '}') | ||
| { | ||
| depth--; | ||
| } | ||
| else if (c == ';' && depth <= 0 && ++seen >= statements) |
There was a problem hiding this comment.
Minor robustness gap in the guard itself: StatementSpanFrom skips verbatim (@"...") and regular ("...") string content when counting semicolons, but it does not skip C# // or /* ... */ comments. A semicolon inside a comment placed between a command construction and its follow-up CommandTimeout = ...; statement (the two-statement window the CreateCommand shape relies on) would end the scanned span early, so the pin could report a correctly-timed site as an offender.
None of the current 45 sites trigger this — I checked each CreateCommand site in DarlingPostgresAlertReadAdapter.cs and none has an interposed comment — but it's a latent false-positive (CI flake) waiting for the next contributor who adds an explanatory comment in that exact spot, which this codebase's style otherwise encourages. Worth a short-circuit for // and /* */ alongside the existing string skips, given how much this guard is relied on to stay accurate.
There was a problem hiding this comment.
Fixed, and proved load-bearing rather than assumed. Built the exact shape you described — a CreateCommand site with an interposed comment containing a semicolon — and confirmed the scanner reports it as an offender WITHOUT comment-skipping and clean WITH it.
You are right that it is the false-positive direction that matters: a guard that fails a green build on correct code is worse than one that misses, because it trains people to distrust the pin. And the gap is exactly where this codebase would put a comment, since the two-statement window exists for the CreateCommand shape whose deadline is the statement after the construction.
// and /* */ are now skipped alongside the string literals. I also added a Theory over StatementSpanFrom itself — forty-five sites' correctness is asserted through that scanner, so its blind spots are worth pinning directly: the comment gap, the verbatim-SQL construction whose deadline sits past any fixed line window, and a genuinely untimed site as the negative control.
|
Reviewed the diff and cross-checked against the repo state (not just the diff hunks). Coverage verified by hand. Grepped all six alert-pass source files for both Exclusion claim checked. Constants checked against the doc comment's own numbers. Lite parity. No Lite counterpart exists for Security/correctness. All touched sites remain fully parameterized ( One inline nitpick on the new test's statement-span scanner (a latent false-positive risk, not tripped by anything in this PR). Otherwise this is thorough, well-bounded, and matches the stated conventions — nothing else to flag. |
StatementSpanFrom skipped string literals but not // or /* */ comments, so a semicolon inside a comment placed between a CreateCommand construction and its follow-up CommandTimeout statement would end the scanned span early and report a correctly-timed site as an offender. None of the current 45 sites trigger it, but it is latent precisely where this codebase's style puts an explanatory comment — the two-statement window exists for the CreateCommand shape, whose deadline is the statement AFTER the construction, and that gap is exactly where someone would explain why. A false positive in a guard is worse than a miss: it fails a green build on correct code and trains people to distrust the pin. Proved load-bearing on the exact shape the review described: without comment-skipping the scanner reports a correctly-timed CreateCommand site as an offender; with it, clean. Added a Theory over the scanner itself, since forty-five sites' correctness is now asserted through it — covering the comment gap, the verbatim-SQL construction whose deadline sits past any fixed line window, and a genuinely untimed site as the negative control. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MX6HyjsuDCs15qGB2rh4Gy
|
Reviewed the diff against CONTRIBUTING.md conventions, Lite/Darling parity, correctness, and security. Findings: none. This is a tightly-scoped, well-verified change and I could not find a defect in it. Specifically checked and confirmed against the actual code (not just the PR narrative):
No inline comments to post since nothing rose to a reportable finding. |
…w source Three corrections, two from other lanes and one from review. Review caught that TryReadEndpointTogglesAsync's linked CTS and its command deadline were the same duration, so which one fires is a race - and the arms report differently. The CTS surfaces as OperationCanceledException and takes the "did not answer within N seconds" arm; an Npgsql CommandTimeout expiry falls through to the general arm and renders "Exception while reading from stream", which is the #2826 costume, handed to an installer by the one site whose purpose is to explain the failure. Flagged non-blocking; it is not, because it undercut the reason the constant exists. The budgeted site now takes CliBudgetBackstopSeconds = CliStoreReadSeconds + 5, which is the same ordering rule the HypoPG forward path uses against the server-side GUC with a client-side CTS as the authoritative bound instead. Pinned as an ordering AND a placement, since the ordering alone would be satisfied by the backstop leaking onto one of the two verbs no budget encloses. The pin matched its value regexes over StatementSpanFrom's span cut from RAW source, so a CommandTimeout written in a COMMENT inside the two-statement window made an untimed site read clean - #2940's finding, inherited from every landed pin in this sweep. StripCommentsAndStrings is length-preserving, so the span is now cut from the stripped text at the same offsets. Proven on real source by commenting out this group's own hypopg_reset() deadline. And store connection acquisition is out of both store-side floors: #2940 measured the connect phase tracking the connection string's Timeout rather than CommandTimeout, so #2819's 673-893ms is outside what these constants bound. The force-plan floor is now #2882's 1,744.9ms production cold read instead of a container figure, and the note says plainly that the ceiling fixes that number while the floor only rules out the bottom two seconds.
…lingdata#2874) DarlingWorker.ReadLatestCpuAsync is the first read EvaluateAlertsAsync performs, on every server, on every 30s tick, and it set no CommandTimeout - so it inherited Npgsql's undocumented 30s default and would surface a deadline as "Exception while reading from stream". It takes DarlingAlertReadAdapter.AlertPassCommandTimeoutSeconds, the value erikdarlingdata#2882 derived for exactly this regime: no enclosing budget, bounded below by a measured 1,744.9ms worst-case read and above by the 30s s_alertSweepInterval the pass runs on. No new number. AlertPassCommandTimeoutTests scoped itself with a hardcoded array of six filenames and DarlingWorker.cs was not one, so the guard declared the pass clean while this site sat on the default. The scope now also walks the transitive closure of calls out of EvaluateAlertsAsync, so the claim is computed rather than restated: a read added to any member the pass reaches is covered when it is written. A whole-file sweep of DarlingWorker.cs could not do this - it holds seven command sites across four budgets, six of them deliberately owned by other groups.
…er regimes Thirteen command sites, four derivations, because these regimes disagree about which direction is dangerous. hypopg_reset() is the inverted one. It runs post-rollback, so the SET LOCAL statement_timeout no longer applies (measured: SHOW reads 0 and pg_sleep(8) completes in 8.01s immediately after ROLLBACK), and it takes CancellationToken.None so no token bounds it either. Its CommandTimeout is the only bound it has. A client-side timeout on a RESPONSIVE backend leaves the connection Open and the phantom hypothetical index in the pool - same backend pid on re-borrow - while a responsive backend would have completed a 0.24-0.93ms memory free. So the value goes UP, to 6x the forward path. It stays finite because a timeout against an unresponsive backend breaks the connection and the pool discards it, which is the correct outcome, while 0 would pin a command-plane worker on an unreachable server forever. The forward path goes the other way, 60s to 20s, derived strictly ABOVE the 15s server-side GUC so PostgreSQL's diagnosable 57014 keeps winning over Npgsql's "Exception while reading from stream". PostAnalysisForcePlanSeconds bounds what erikdarlingdata#2882 deferred, against the 120s analysis pass the hook rides on rather than a cadence. CliStoreReadSeconds is not a new number - TryReadEndpointTogglesAsync already derived ten seconds and prints it to the operator, and the command inside it plus two sibling verbs never got it. And --recompress-plan-dim's plan-codec preflight now reports its failure instead of throwing out of the process: it was the one store call in that verb with no handler, and Program.cs's verb dispatch has none either, so a deadline there would only have changed how long the stack trace took. No schema change, no version bump.
1 participant
Part of #2874 — one group of several. Does not close it.
The group: the alert evaluation pass, 45 sites across 6 types
Grouped by the budget the sites actually run under, not by file. These seven types make up one alert evaluation pass, which
DarlingWorkerruns sequentially inside the per-server sweep body:DarlingAlertReadAdapterPgAlertStateStorePgMuteRuleStoreDarlingSelfAlertEvaluatorDarlingPostgresAlertReadAdapterPgAlertHistoryStoreAll 45 set no
CommandTimeout. This is live, not theoretical: on 2026-09-04 the forced-plan read failed five times on the production store, each surfacing asException while reading from stream— which is how Npgsql renders its OWN deadline, and reads literally as though the network broke. That is precisely the misdiagnosis #2826 exists to prevent.Why this group could not take the 60s the two closed passes use
#2810 and #2871 both sit under
DarlingWorker.s_analysisTimeout— a 120sCancelAfterthat bounds the whole pass no matter how long any single command runs. Their per-command value had to fit below that.This pass has no enclosing budget at all.
EvaluateAlertsAsyncis called with the plain stopping token; there is noCancelAfteranywhere on the path. So the per-command deadline is the pass budget, multiplied by however many reads run in sequence — and the body holds one of onlyMaxConcurrentServerSweeps= 4 fleet permits for its entire duration, with that server's sweep relaunch skipped throughout.At the inherited 30s that is 45 x 30s of worst-case exposure against 25% of fleet sweep capacity. Copying 60s here would have doubled it.
The bound, both sides
Below — measured. The shipped query strings were dumped from the built assembly by reflection (not retyped) and timed against the production store's three busiest servers, cold and warm, via
EXPLAIN (ANALYZE, BUFFERS):The whole pass's cost is one read, 620x the next slowest. 10s is 5.7x that worst case, so it absorbs a substantial stall rather than only the happy path.
Above — the cadence.
s_alertSweepIntervalis 30s, so one stalled read must still leave the pass able to finish inside the interval that will start it again.The asymmetry is why erring SHORT is right, and it reverses #2810's direction. An exceeded deadline skips one alert check, logs it, and retries 30s later — one cycle of delay on one alert. A long-running read holds a fleet sweep permit and delays collection for every other server queued behind it. The recoverable failure is strictly cheaper, so this is the first value in the family set below what it inherited.
What the data cannot say. Every observed failure was killed at the 30s ceiling, so the record is right-censored — nothing establishes whether a stalled read wanted 35s or 300s. 10s is chosen from the measured cost and the cadence above, not fitted to a distribution the data cannot show.
#2874's census undercounts, and the pin covers what it missed
The issue counted 133 untimed sites by scanning
new NpgsqlCommand(. That is not the only shape —NpgsqlDataSource.CreateCommand(sql)hands out a command with the same inherited default, and the census misses it entirely. Four of this group's own sites are that shape.A repo-wide recount across both shapes is on the issue. The pin here matches both, so a guard keyed to one spelling cannot declare this family clean while a fifth of a file stays on the default — the #2786 shape exactly.
The pin scans by statement, not by a line window. The first draft used a 12-line window and reported three patched sites as offenders, because these sites embed verbatim SQL and the construction routinely spans 20+ lines. Widening the window would be worse: it would read the next command's deadline and report an untimed site as clean.
Review correction (applied)
Review caught that
PgPlanForceActionStoreis not in this pass at all — its only caller isPlanForceBot.RunAfterAnalysisAsync, dispatched as the analysis pass's post-pass hook. Verified: the hook is built atDarlingWorker.cs:4084closing over the plainstoppingToken, so although invoked lexically inside thetryowningpassCts, it runs outside that 120sCancelAfter.Those 4 sites were dropped from this PR rather than renaming the constant to something pass-agnostic. The two passes share the unbudgeted shape but not the cadence, and the upper bound here is derived specifically from the 30s
s_alertSweepInterval— a pass-agnostic name would have made that bound look general when it is not. They need their own measurement and are left for their own group on #2874, with the exclusion documented in both the constant and the pin so they are not re-added by resemblance.Verification
Darling.Testsisnet10.0-windowsand cannot run on macOS, so the assertions were replicated in anet10.0harness against the real built assembly, reading the constant by reflection so each rebuild is visibly picked up.Proved red three ways, each failing a different assertion:
Note the restore after the first variant over-reverted (a plain
git checkouttook the file back toorigin/dev, dropping all six of its patches, not the one removed); the follow-up verification run caught it at 6 offenders and it was re-applied.Scope
133 -> the true figure is higher; this group closes 45. Remaining groups and the corrected census are recorded on #2874. Lite is out of scope —
DuckDBCommand.CommandTimeoutdefaults to 0, so the mechanism cannot occur there.No migration rung, no
StorageVersion.SchemaVersionbump. CHANGELOG staged 2 insertions / 0 deletions with a plaingit add— #2858's renormalization is holding.🤖 Generated with Claude Code
https://claude.ai/code/session_01MX6HyjsuDCs15qGB2rh4Gy