Let the server's statement timeout win on web composed panels, and record a client timeout as Timeout (#4605)

[erikdarlingdata]

On the web compose path the client CommandTimeout equalled the role's server-side statement_timeout (both 60 s), so they raced. When Npgsql's client timer won it threw an NpgsqlException wrapping a TimeoutException, which fell into the generic arm, recorded Error and showed "Error running query". Production showed three query_stats and three procedure_stats runs of about 61 s with zero recorded timeouts.

Change

• DarlingWebEndpoints.ComposeClientDeadlineHeadroomSeconds (5 s, one named constant) is added to the resolved composed-query seconds for the main query, the annotation queries and the server-clock read. The runner parameters that receive it are named clientDeadlineSeconds. The web /api/compose/run route passes it. The MCP run_custom_view_panel caller passes no headroom, so its deadline is unchanged and its two deadlines still race; it does pass the remap flag (below), so either side's timeout gives the same answer.
• Where a failure happened decides what it is, not its message. Both compose runners open their store connection through one helper, OpenComposeConnectionAsync, before their statement try:
  • an NpgsqlException from the open (pool wait, DNS, TCP connect, TLS/startup or login exchange; a PostgresException the server sent at login keeps its existing arm) is raised as ComposeStoreOpenException;
  • an NpgsqlException over a TimeoutException raised while the statement executes (ExecuteReaderAsync or the row loop) is raised as ComposeStatementClientTimeoutException. Two cases look the same to the driver and also become this marker: a stalled send of the query, and a pooled connection whose peer went away. One limit, documented on the marker: with Multiplexing=true in a bring-your-own store connection string, a connect failure surfaces from ExecuteReaderAsync too. The managed store's connection string does not set it (Npgsql's default is off).
• FromRunException(ex, remapClientTimeout): with the flag on (the web route and the MCP tool both pass it; the default is off and no production caller uses it), the statement marker becomes the author-actionable 57014 outcome with the same text the server timeout gives, so the run records Timeout and MCP answers status "invalid", as the tool description says. The open marker answers a server error, recorded as Error and logged at Error with the original message: "Error running query: could not get a store connection in time: " for a timeout, "Error running query: could not open a store connection: " otherwise. Everything else stays Error running query: ....
• The client deadline also fires first, with the same Timeout outcome, in two cases the doc names: a pooled session that keeps an older, higher statement_timeout after an operator lowers the compose setting, and the owner-login fallback, which has no server-side statement_timeout.
• WebExceptionTextCensusTests allow-lists the new sentences, with reasons that describe the current code.
• Dev is merged in (Custom Views panels, Active Queries and Current Waits say where their data starts #4953, collection_log compresses by server and collector (#4951) #4959, Order the latest collector outcome read by collection_time first (#4974) #4975, Lite and Darling stop dropping Extended Events sessions that another install reads (#4961) #4967). Custom Views panels, Active Queries and Current Waits say where their data starts #4953's data-start probe keeps the server-side composedQuerySeconds deadline on purpose: it swallows and logs its own failure, so the client-timeout attribution does not apply to it.

Collisions checked

• Revisit the WPF viewer's and storage-layer MCP readers' client deadlines against the 60 s store ceiling, with measured read durations #4450 (viewer 15 s and storage-MCP 30 s client deadlines vs the 60 s ceiling) and Raise the viewer and mcp roles' default statement_timeout from 15 s to 60 s (#4442) #4447 (role timeout 15 s -> 60 s; viewer/storage-MCP deadlines kept at their Viewer: InteractiveReadSeconds (15s) is derived from a single-read measurement but bounds ten-wide concurrent fan-outs #3004 values): neither value is touched.
• PairedClientDeadlinesTests pins McpCommandDeadlines.ReadSeconds above the ceiling, ComposedQueryFallbackSeconds equal to it, and the viewer/storage deadlines below it. None changes; the resolved compose value and the fallback are untouched, only the value handed to CommandTimeout on the web path moves.
• Viewer: InteractiveReadSeconds (15s) is derived from a single-read measurement but bounds ten-wide concurrent fan-outs #3004 bands unchanged. No WPF, CustomAlertEvaluator or storage reader code touched.

Tests

• ComposeClientTimeoutAttributionTests (17, no PostgreSQL):
  • behaviour: the statement marker maps to Timeout with the 57014 text (compared with FromPostgresException's output) with the flag on and keeps the generic error with it off; the open marker answers the open sentence for the pool text, "Failed to connect", the DNS-shaped "The operation has timed out" and the TLS/startup-shaped "Exception while reading from stream", with the flag on and off, never 57014; a non-timeout open failure answers "could not open a store connection"; other exceptions are unchanged;
  • wiring, read through RepoFile with comments and strings stripped: the route's and the MCP tool's whole argument lists (Assert.Equal); ComposeClientDeadlineSeconds(composedQuerySeconds, clientDeadlineHeadroomSeconds); command.CommandTimeout = clientDeadlineSeconds; exactly twice; in each runner the open comes before the statement try and ExecuteReaderAsync only inside it; the statement marker thrown exactly twice and the open marker once.
• ComposeOpenPhaseTimeoutTests (3, no PostgreSQL): a TCP listener that accepts and never answers drives the open for real (Timeout=1): the runner answers "could not get a store connection in time" as a server error with the remap flag on and off, and a POST to /api/compose/run answers 500, not a 400 with the 57014 text.
• ComposeTimeoutPhaseLiveTests (2, own scratch store): with a one-connection pool held, the run answers the open sentence and "connection pool has been exhausted"; with the panel's table held under ACCESS EXCLUSIVE and a 5 s compose timeout (asserted as what the runner resolves), the client deadline fires inside the statement and the run answers 57014 with the statement-timeout text, in under 60 s (about 44 s here: a coverage read before the measure query waits on the same lock under its own deadline).

Each finding shown RED with its fix undone (temporary edit, reverted, GREEN again)

Finding	Mutation	RED
The tests catch the fix: open phase	the runner opens through postgres.CreateCommand(...) again (the open happens inside the statement try)	ComposeOpenPhaseTimeoutTests 3 of 3 (both flags and the route), the pool fact in ComposeTimeoutPhaseLiveTests, and the source pins EachRunner_OpensTheConnectionBeforeTheStatementTry(RunComposedQueryAsync) and TheMarkers_AreThrown…
The tests catch the fix: statement phase	both statement catch filters disabled (when (false); deleting them leaves a try without a catch)	the statement-phase fact in ComposeTimeoutPhaseLiveTests (generic server error instead of 57014), and TheMarkers_AreThrownFromTheOneOpenHelperAndTheTwoStatementCatches
Exact wiring arguments	MCP passes readLatency, 5, true; the runner computes ComposeClientDeadlineSeconds(composedQuerySeconds, 0); one runner sets command.CommandTimeout = 30;	TheMcpCaller_PassesNoHeadroom_AndTheRemapFlag; TheRunner_PassesTheClientDeadlineToTheMeasureAndAnnotationQueries (each, 1 of 17)
Open failures classified by where they failed	FromRunException's open-marker arm disabled	OpenTimeout_IsAServerErrorNamingTheOpen_NotAStatementTimeout ×4 and OpenFailure_WithoutATimeout_AnswersCouldNotOpen (5 of 17)
MCP answers the documented status	MCP drops remapClientTimeout: true	TheMcpCaller_PassesNoHeadroom_AndTheRemapFlag
The live statement test runs under its 5 s deadline	the seed back to a plain UPDATE ... WHERE id = 1 (matches no row on a fresh store)	ABlockedStatement_…: Expected 5, Actual 60

Verified locally at 3bd013dec (Release, --no-incremental; Darling.Tests in-process on a local TimescaleDB 2.30.1 rig): Darling.Tests and Lite.Tests build with 0 warnings, 0 errors. 0 failed: ComposeClientTimeoutAttributionTests 17, ComposeOpenPhaseTimeoutTests 3, ComposeTimeoutPhaseLiveTests 2, WebExceptionTextCensusTests 40, DarlingComposeTests 305, ComposeDataFloorLiveTests 14, ComposeRollupDataFloorLiveTests 2, ComposeSourceRouterTests 30, McpReadCommandTimeoutTests 43, StorageCommandTimeoutTests 19, StartupCommandTimeoutTests 15, ReadLatencyPerServerRecordingTests 2, McpPayloadContractCensusTests 68, McpToolGuideTests 10, McpToolGuideHeadsDataTests 3, McpToolsListBudgetTests 5, the whole-tree guards (TsqlConventionGuardTests 14, DocCommentHygieneTests 77, RepoFileAdoptionTests 2, CommandDeadlineScannerAdoptionTests 1, CommentFilterAdoptionTests 4) and the census classes run. LivePostgresCollectionHygieneTests does not run on macOS: ComposeTimeoutPhaseLiveTests carries the #1776 own-store marker, and ComposeOpenPhaseTimeoutTests uses no store.

Refs #4605

CHANGELOG

SECTION: Fixed
ENTRY: - Custom Views panels that hit the 60 s limit say so ([#4976]) - a panel whose query runs out of time, on the web page or through the run_custom_view_panel MCP tool, now reports the timeout with the actionable text instead of "Error running query", and a panel that cannot get a store connection in time says that instead.
REF: [#4976]: #4976

[erikdarlingdata]

Claude posting for Erik Darling

This is a read-only check of 79417e2 against Npgsql 10.0.3, the version that Directory.Packages.props pins. I ran no tests and no builds.

Result: 2 defects to fix and 3 notes. Each inline comment gives the evidence and a fix.

1. Defect (line 1099): FromRunException gives the 57014 statement-timeout answer to more than the command timer. A pool wait, a connect, a DNS lookup or a write that times out gets it too. The service log then loses the real cause.
2. Defect (test file): no test pins the wiring. If the route stops passing the headroom, or if the catch stops remapping, all 5 new tests still pass.
3. Note (line 1382): the web-path flag comes from headroom > 0, and webPath defaults to true.
4. Note (line 1082): the 5 s margin and the bound on a run. Two cases still let the client deadline fire first.
5. Note (below, no diff line): the MCP surface keeps the equal-deadline race.

What Npgsql 10.0.3 does when CommandTimeout expires

1. The read timer expires. CommandTimeout is a timer on each socket read (NpgsqlConnector.cs line 2903, NpgsqlReadBuffer.cs lines 183-185).
2. Npgsql sends a CancelRequest on a new connection (PerformPostgresCancellation, NpgsqlConnector.cs lines 2201-2229). Then it reads for CancellationTimeout more, which is 2 s by default (NpgsqlReadBuffer.cs lines 214-227).
3. The backend answers 57014 "canceling statement due to user request". NpgsqlConnector.cs lines 1790-1801 see 57014 with PostgresCancellationPerformed set. They throw NpgsqlException("Exception while reading from stream", new TimeoutException("Timeout during reading attempt")), and the connection stays usable.
4. If no answer arrives in that time, the connector breaks. NpgsqlReadBuffer.cs lines 232 and 241-250 throw the same pair.

So when the client timer fires first, the web path never sees a PostgresException. It sees the pair that the new test builds. Step 3 also converts a server 57014 that arrives after the client cancel started. This agrees with equal deadlines that recorded no timeouts.

Claims

Claim	Grade	Evidence
Before this change, the web client deadline equalled the role statement_timeout	VERIFIED	Dev passed composedQuerySeconds to both calls (old lines 1303 and 1307). DarlingManagedRoles.cs lines 445-446 write the same value onto the viewer and mcp roles.
A client-timer win threw NpgsqlException over TimeoutException and recorded Error	VERIFIED	The Npgsql steps above. Line 1200 records Error for a ServerError outcome.
The browser then showed "Error running query"	REFUTED (minor)	The browser got the fixed GenericMessage at 500 through ServerErrorResult (line 1533). The "Error running query" sentence went only to the service log.
Three query_stats and three procedure_stats runs of about 61 s, with zero timeouts	UNVERIFIED	Production data. Both surfaces record ReadSurface.Compose with the same compose:<source> label (line 1202), so the census cannot separate web runs from MCP runs.
The headroom applies to the main query, the annotations and the server-clock read	VERIFIED	Lines 1332, 1333 and 1337, then lines 1646, 1650, 1612 and 1665.
The web endpoint passes the headroom	VERIFIED (not tested)	Line 604. No test pins it. See defect 2.
MCP passes 0, and its deadline and answer do not change	VERIFIED (not tested)	DarlingMcpCustomViewTools.cs line 287 omits the argument, so the default 0 applies. Line 1382 then passes false, and line 1104 returns the old text.
A wrapped client timeout maps to 57014 with the server's text and records Timeout	VERIFIED	Lines 1099-1101, then lines 1192-1193. The test compares the text with FromPostgresException.
The client timeout "is the same event as the server's 57014" (doc, line 1094)	REFUTED	The predicate also matches timeouts that never sent a statement. See defect 1.
The census allow-list entry reads no exception text	VERIFIED	WebExceptionTextCensusTests.cs lines 88-93. The matched line reads no text.
No constant that PairedClientDeadlinesTests, #4447 or #4450 pins moves, and the #3004 bands do not change	VERIFIED	The diff changes 3 files: DarlingWebEndpoints.cs and two test files. ReadSeconds, ComposedQueryFallbackSeconds, InteractiveReadSeconds and McpReadSeconds are not in it.
RED (2 tests fail), GREEN (5/5), the suite counts and the builds with 0 warnings	UNVERIFIED	Not run. By reading, tests 1 and 3 are the two that fail with headroom 0 and the old mapping.
The live census test runs in CI	UNVERIFIED	Not run.

Callers of a changed signature

• RunComposedPanelAsync gets the optional clientDeadlineHeadroomSeconds. Line 604 (web) passes 5. DarlingMcpCustomViewTools.cs line 287 (MCP) omits it, so 0 applies. DarlingComposeTests.cs lines 3471 and 3518 omit it. Those tests check windows and routing, so the default does not affect them. McpReadCommandTimeoutTests.cs line 437 scans for the declaration text, which did not change, and the resolve still sits between the runner and RunComposedQueryAsync.
• RunComposedPanelCoreAsync is private. Its one caller is line 1146.
• FromRunException and ComposeClientDeadlineSeconds are new. Each has one production caller, at lines 1382 and 1332.

All of these callers are correct.

Note: the MCP surface keeps the race

run_custom_view_panel keeps a client deadline equal to the mcp role's statement_timeout. Its runs can still lose the race and record Error. If any of the six 61 s runs came through MCP, this change does not move them. We recommend that the runner records Timeout for an MCP client timeout too, so that the census counts both surfaces the same way. The MCP answer text does not need to change. For example, carry a client-timeout flag on the outcome that only RecordComposeLatency reads.

[erikdarlingdata]

Claude posting for Erik Darling

Second check of this PR. It covers only the change from 79417e2 to 0aefc42 (3 files). I built nothing and ran no tests. I read the Npgsql behaviour from the v10.0.3 tag, which is the version that Directory.Packages.props pins.

The four claims of this change

1. Claim: only a timeout inside ExecuteReaderAsync or the row loop becomes the marker. Only the marker maps to 57014. VERIFIED. Both runners open the connection before the try (DarlingWebEndpoints.cs:1647 and 1708). The catch filters wrap only the execute and the reads (1656-1673, 1716-1724). FromRunException remaps only the marker (1117-1121). Three cases still reach the marker without a statement. See the note on line 1096.
2. Claim: a pool or connect timeout answers a server error that names the cause. Both callers record Error. PARTLY VERIFIED. The pool text starts with "The connection pool has been exhausted" (Npgsql PoolingDataSource.cs:176-179). A TCP connect timeout starts with "Failed to connect" (NpgsqlConnector.cs:1452-1459). Both callers go through RecordComposeLatency. It records Error for a server error with no SQLSTATE (1223-1233). A DNS timeout and a timeout in the TLS, startup or login exchange are not named: REFUTED for those shapes. See the comment on line 1124.
3. Claim: the remap flag defaults to false, and only the web route passes true. The deadline parameter has a new name. VERIFIED. Callers of RunComposedPanelAsync are the web route (604, true), DarlingMcpCustomViewTools.cs:287, and DarlingComposeTests.cs:3471 and 3518. The last three pass no flag. FromRunException has one production caller (1415). The tests pass the flag by name. So the default, which changed from true to false, breaks no caller. The renamed private methods have the callers at 1366, 1370, 1690 and 1694.
4. Claim: the class has 11 tests, and each wiring pin goes red when its call site changes. The count is VERIFIED. Red on mutation is UNVERIFIED, because I ran no tests. From the source, two mutations bring back the two bugs and leave all 11 tests green. The MCP pin also passes positional arguments. See lines 122 and 166 of the test file.

Question 3: can an open timeout reach the statement catch?

It cannot, for the pool as shipped: VERIFIED. OpenConnectionAsync takes a connector from the pool (Npgsql NpgsqlConnection.cs:277-300). ExecuteReader then uses that bound connector and opens nothing (NpgsqlCommand.cs:1400-1415). Npgsql does not reconnect inside a command.

Each measure, annotation and server-clock query opens its own connection outside its own try. The deadline read and the rollup probe swallow their own failures (McpCommandDeadlines.cs:195-206, ComposeStoreAvailability.cs:206-219). So with a full pool, the open at line 1647 is the first wait that fails the run. This change moved that open.

Question 2: the MCP text

No census or pin reads the error text of run_custom_view_panel. McpPayloadContractCensusTests looks for Status("error", and this tool builds its answer with Outcome(...), as before. A pool or connect timeout still answers status "error". The description says that "error" is for an internal fault. The web sentence classifier is anchored on "57014: ", so the new sentences still answer 500 with the fixed body. One disagreement with the description is in the comment on line 1119.

Findings

4 findings need a code change: test file lines 122 and 166, and DarlingWebEndpoints.cs lines 1119 and 1124. 3 findings are notes. I found no problem in the other changed lines.

[erikdarlingdata]

Claude posting for Erik Darling

Follow-up check of the four findings in the last review, at 3bd013d. For each finding, I put the bug back with a temporary edit and ran the targeted test classes. Then I restored the file, rebuilt and ran the classes again. All four findings PASS.

1. The tests cover the fix: PASS

The fix adds ComposeOpenPhaseTimeoutTests. It drives the open phase for real against a local listener that accepts the TCP connection and never answers. It runs the runner with each flag value, and it POSTs to /api/compose/run. Source pins check the open order and the marker throws.

• (a) RunComposedQueryAsync opens through postgres.CreateCommand(compiled.Sql) again, so the open happens inside the statement try. RED, 5 tests fail:
  • ASilentStore_IsAServerError_NotTheStatementTimeoutText(remapClientTimeout: True): Assert.True(outcome.IsServerError) fails with "Query failed: canceling statement due to statement timeout".
  • The same test with False: Assert.StartsWith() Failure. The actual text is "Error running query: The operation has timed out".
  • ASilentStore_AnswersTheComposeRoute_WithA500_NotA400CarryingTheTimeoutText: Assert.Equal() Failure, expected 500, actual 400.
  • The pins EachRunner_OpensTheConnectionBeforeTheStatementTry (RunComposedQueryAsync case) and TheMarkers_AreThrownFromTheOneOpenHelperAndTheTwoStatementCatches.
• The same edit in ReadServerClocksAsync only: TheMarkers_... and the ReadServerClocksAsync case of the open-order pin fail. The real-drive panel has no annotations, so only the pins cover that runner.
• (b) Both statement catches deleted, with their try keyword, so that the file compiles. RED, 3 tests fail: TheMarkers_AreThrownFromTheOneOpenHelperAndTheTwoStatementCatches at line 212 with Assert.Equal() Failure, expected 2, actual 0, and both cases of the open-order pin.
• GREEN after each restore: all 20 pass.
• Judged by reading, needs PostgreSQL. With (a), AnExhaustedPool_IsAStoreConnectionError_NotTheStatementTimeoutText would fail at Assert.True(outcome.IsServerError), because the pool wait would become the statement marker. With (b), ABlockedStatement_BecomesTheStatementTimeoutText_WhenTheClientDeadlineFires would fail at Assert.Equal("57014", outcome.AuthorSqlState). The scratch login has no role statement_timeout, so the client deadline is the only bound. Its timeout would then fall to the generic arm. Both tests skip here.

2. Exact wiring arguments: PASS

The pins compare the whole argument list of both callers. They also require the ComposeClientDeadlineSeconds arguments and count the two command.CommandTimeout = clientDeadlineSeconds; lines.

• The MCP call with (postgres, body, CancellationToken.None, readLatency, 5, true). RED: TheMcpCaller_PassesNoHeadroom_AndTheRemapFlag fails at line 164 with Assert.Equal() Failure: Strings differ.
• One command.CommandTimeout = clientDeadlineSeconds; changed to = 30;. RED: TheRunner_PassesTheClientDeadlineToTheMeasureAndAnnotationQueries fails at line 175 with Assert.Equal() Failure, expected 2, actual 1.
• ComposeClientDeadlineSeconds(composedQuerySeconds, 0). RED: the same test fails at line 172 with Assert.Contains() Failure: Sub-string not found.
• GREEN: 17 of 17.

3. Open failures are named by where they happen: PASS

OpenComposeConnectionAsync wraps each non-Postgres NpgsqlException from the open in ComposeStoreOpenException, before the statement try. FromRunException picks the sentence from the marker type and from the inner TimeoutException. No message-prefix check is left.

• Prefix classification put back. Only "The connection pool has been exhausted" and "Failed to connect" get the named sentence, and the non-timeout arm stays. RED, 4 tests fail:
  • OpenTimeout_IsAServerErrorNamingTheOpen_NotAStatementTimeout with "The operation has timed out" and with "Exception while reading from stream": Assert.StartsWith() Failure. The actual texts are "Error running query: The operation has timed out" and "Error running query: Exception while reading from stream".
  • Both ASilentStore_IsAServerError_NotTheStatementTimeoutText cases, with the same assertion. The real open timeout answered "Error running query: The operation has timed out".
  • The pool and connect cases stay green.
• The open's exception let through (the catch in the open helper removed). RED, 3 tests fail: both ASilentStore_IsAServerError_... cases with the same text, and TheMarkers_... with Assert.Single() Failure: The collection was empty.
• The statement client timer is mapped as before. The marker arm and the two statement catch filters have not changed since 0aefc42. StatementPhaseClientTimeout_OnTheWebPath_MapsToTimeoutWithTheActionableText and StatementPhaseClientTimeout_WithoutTheRemapFlag_KeepsTheGenericServerError passed in every run, including the mutated runs.
• GREEN: 20 of 20.

4. The MCP status matches the documented error shape: PASS

DarlingMcpCustomViewTools.cs:290 passes remapClientTimeout: true with no headroom. A client-timer timeout then answers status "invalid" with the 57014 text and records Timeout. That matches the description at lines 245-246.

• Flag dropped. RED: TheMcpCaller_PassesNoHeadroom_AndTheRemapFlag fails at line 164 with Assert.Equal() Failure: Strings differ. The actual call ends at readLatency.
• GREEN: 17 of 17.

Build

Darling.Tests (Debug) at 3bd013d: Build succeeded, 0 warnings, 0 errors. At the head, ComposeClientTimeoutAttributionTests passed 17 of 17 and ComposeOpenPhaseTimeoutTests passed 3 of 3. ComposeTimeoutPhaseLiveTests skipped 2 (no PostgreSQL). WebExceptionTextCensusTests passed 39 and skipped 1. Every temporary edit was restored with git checkout, and the tree is clean.