diff --git a/Darling/Darling.Tests/ComposeClientTimeoutAttributionTests.cs b/Darling/Darling.Tests/ComposeClientTimeoutAttributionTests.cs index 595edcea11..dba536e839 100644 --- a/Darling/Darling.Tests/ComposeClientTimeoutAttributionTests.cs +++ b/Darling/Darling.Tests/ComposeClientTimeoutAttributionTests.cs @@ -231,4 +231,16 @@ public void TheGenericCatch_RemapsThroughTheFlag() { Assert.Contains("return FromRunException(ex, remapClientTimeout);", WebCode(), StringComparison.Ordinal); } + + [Fact] + public void TheOpenHelper_ClocksTheOpen_AndFlagsALateFailure_AndTheSentenceReadsTheFlag() + { + var code = WebCode(); + var helper = MethodBody(code, "private static async Task OpenComposeConnectionAsync("); + + Assert.Contains("Stopwatch.StartNew()", helper, StringComparison.Ordinal); + Assert.Contains("PostgresOpenTimeout.IsTimedOutByClock(open.Cause, started.Elapsed, timeout, cancellationToken.IsCancellationRequested)", helper, StringComparison.Ordinal); + Assert.Equal(1, Regex.Matches(helper, Regex.Escape("{ FailedAfterTimeout = true }")).Count); + Assert.Contains("|| open.FailedAfterTimeout", code, StringComparison.Ordinal); + } } diff --git a/Darling/Darling.Tests/ComposeOpenPhaseTimeoutTests.cs b/Darling/Darling.Tests/ComposeOpenPhaseTimeoutTests.cs index 66fdd4db88..213a436c24 100644 --- a/Darling/Darling.Tests/ComposeOpenPhaseTimeoutTests.cs +++ b/Darling/Darling.Tests/ComposeOpenPhaseTimeoutTests.cs @@ -102,6 +102,28 @@ public void Dispose() } } + /// Every level of the chain the compose runner caught: type, message, and the socket code or HResult that + /// says what the operating system did. + private static string DescribeChain(Exception? ex) + { + var sb = new System.Text.StringBuilder("exception chain:"); + for (var level = ex; level is not null; level = level.InnerException) + { + sb.Append(System.Globalization.CultureInfo.InvariantCulture, $"{Environment.NewLine} {level.GetType().FullName}: {level.Message}"); + if (level is System.Net.Sockets.SocketException se) + { + sb.Append(System.Globalization.CultureInfo.InvariantCulture, $" [SocketErrorCode={se.SocketErrorCode}]"); + } + + if (level is System.IO.IOException) + { + sb.Append(System.Globalization.CultureInfo.InvariantCulture, $" [HResult=0x{level.HResult:X8}]"); + } + } + + return sb.ToString(); + } + [Theory] [InlineData(true)] [InlineData(false)] @@ -111,13 +133,15 @@ public async Task ASilentStore_IsAServerError_NotTheStatementTimeoutText(bool re await using var store = NpgsqlDataSource.Create(listener.ConnectionString); var body = (JsonObject)JsonNode.Parse(PanelJson)!; + Exception? thrown = null; var outcome = await DarlingWebEndpoints.RunComposedPanelAsync( - store, body, TestContext.Current.CancellationToken, null, DarlingWebEndpoints.ComposeClientDeadlineHeadroomSeconds, remapClientTimeout: remapClientTimeout); + store, body, TestContext.Current.CancellationToken, null, DarlingWebEndpoints.ComposeClientDeadlineHeadroomSeconds, remapClientTimeout: remapClientTimeout, + onRunException: ex => thrown = ex); Assert.True(outcome.IsServerError, outcome.Error); /* The same prefix assertion, with the whole text as the failure message: xunit cuts a StartsWith failure after about fifty characters, which hid the cause when this failed on a loaded runner. */ - Assert.True(outcome.Error!.StartsWith("Error running query: could not get a store connection in time: ", StringComparison.Ordinal), outcome.Error); + Assert.True(outcome.Error!.StartsWith("Error running query: could not get a store connection in time: ", StringComparison.Ordinal), outcome.Error + Environment.NewLine + DescribeChain(thrown)); Assert.NotEqual(DarlingWebEndpoints.StatementTimeoutText, outcome.Error); Assert.NotEqual("57014", outcome.AuthorSqlState); } diff --git a/Darling/Darling.Tests/PostgresOpenTimeoutTests.cs b/Darling/Darling.Tests/PostgresOpenTimeoutTests.cs index cca42d74dd..b51af8992a 100644 --- a/Darling/Darling.Tests/PostgresOpenTimeoutTests.cs +++ b/Darling/Darling.Tests/PostgresOpenTimeoutTests.cs @@ -134,4 +134,56 @@ public void TheHelper_AnswersTheSameAsTheSentence() private sealed class TaskCanceledExceptionStandIn : OperationCanceledException { } + + // ---- #5016 follow-up: the clock decides when the driver's own timer tore the socket down ---- + + private static readonly TimeSpan OneSecond = TimeSpan.FromSeconds(1); + + private static NpgsqlException AbortedRead() => + new("Exception while reading from stream", + new System.IO.IOException("Unable to read data from the transport connection", new SocketException((int)SocketError.OperationAborted))); + + [Fact] // the shape rules alone do not see this one; that is the gap + public void AnAbortedSocketRead_IsNotATimeoutByShape() => Assert.False(PostgresOpenTimeout.IsTimedOutOpen(AbortedRead())); + + [Fact] + public void AnAbortedSocketRead_AtTheTimeout_IsATimedOutOpen() + { + Assert.True(PostgresOpenTimeout.IsTimedOutByClock(AbortedRead(), OneSecond, OneSecond, callerCancelled: false)); + Assert.True(PostgresOpenTimeout.IsTimedOutByClock(AbortedRead(), TimeSpan.FromMilliseconds(950), OneSecond, callerCancelled: false)); + } + + [Fact] + public void AnAbortedSocketRead_WellBeforeTheTimeout_IsNotATimedOutOpen() => + Assert.False(PostgresOpenTimeout.IsTimedOutByClock(AbortedRead(), TimeSpan.FromMilliseconds(50), OneSecond, callerCancelled: false)); + + [Fact] + public void AServerReply_AtTheTimeout_IsNotATimedOutOpen() => + Assert.False(PostgresOpenTimeout.IsTimedOutByClock( + new NpgsqlException("x", new PostgresException("down", "FATAL", "FATAL", "57P01")), OneSecond, OneSecond, callerCancelled: false)); + + [Fact] + public void ACallerCancellation_AtTheTimeout_IsNotATimedOutOpen() + { + Assert.False(PostgresOpenTimeout.IsTimedOutByClock(AbortedRead(), OneSecond, OneSecond, callerCancelled: true)); + Assert.False(PostgresOpenTimeout.IsTimedOutByClock(new NpgsqlException("x", new OperationCanceledException()), OneSecond, OneSecond, callerCancelled: true)); + } + + [Fact] + public void ANestedCancellation_WithTheCallerLive_AtTheTimeout_IsTheDriversTimer_AndTimedOut() + { + Assert.True(PostgresOpenTimeout.IsTimedOutByClock( + new NpgsqlException("Exception while reading from stream", new OperationCanceledException()), OneSecond, OneSecond, callerCancelled: false)); + Assert.True(PostgresOpenTimeout.IsTimedOutByClock( + new NpgsqlException("x", new System.IO.IOException("io", new OperationCanceledException())), OneSecond, OneSecond, callerCancelled: false)); + } + + [Fact] + public void AnOpenThatFailedAfterTheTimeout_AnswersInTime_AndOneThatDidNotKeepsCouldNotOpen() + { + var inner = AbortedRead(); + var late = DarlingWebEndpoints.FromRunException(new DarlingWebEndpoints.ComposeStoreOpenException(inner) { FailedAfterTimeout = true }); + Assert.Equal(InTime + inner.Message, late.Error); + Assert.Equal(NotOpened + inner.Message, Answer(inner)); + } } diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs index 6226154504..0360f3fdc4 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs @@ -1140,6 +1140,13 @@ internal ComposeStoreOpenException(Exception inner) : base(inner.Message, inner) { } + + /// True when the open failed with a driver exception only after the connection Timeout had elapsed + /// (see ), whatever shape the driver wrapped the failure in. + internal bool FailedAfterTimeout { get; init; } + + /// The driver exception this wraps, for classification only (never for answer text). + internal Exception Cause => InnerException!; } /// Opens a compose runner's store connection, before any statement runs. An @@ -1148,6 +1155,42 @@ internal ComposeStoreOpenException(Exception inner) /// . A cancellation propagates unchanged: it is the caller's. private static async Task OpenComposeConnectionAsync( NpgsqlDataSource postgres, System.Threading.CancellationToken cancellationToken) + { + var timeout = OpenTimeoutOrZero(postgres); + var started = Stopwatch.StartNew(); + try + { + return await OpenComposeConnectionCoreAsync(postgres, cancellationToken); + } + catch (ComposeStoreOpenException open) + { + /* The shape rules in PostgresOpenTimeout.IsTimedOutOpen miss a timeout that tore the socket down under the driver + (an aborted read on a loaded runner). Elapsed time covers that without guessing the shape. */ + if (PostgresOpenTimeout.IsTimedOutByClock(open.Cause, started.Elapsed, timeout, cancellationToken.IsCancellationRequested)) + { + throw new ComposeStoreOpenException(open.Cause) { FailedAfterTimeout = true }; + } + + throw; + } + } + + /// The data source's open Timeout, read before the open so a parse failure cannot replace the open's + /// own error; zero (the clock rule off) when the string cannot be read. + private static TimeSpan OpenTimeoutOrZero(NpgsqlDataSource postgres) + { + try + { + return TimeSpan.FromSeconds(new NpgsqlConnectionStringBuilder(postgres.ConnectionString).Timeout); + } + catch (ArgumentException) + { + return TimeSpan.Zero; + } + } + + private static async Task OpenComposeConnectionCoreAsync( + NpgsqlDataSource postgres, System.Threading.CancellationToken cancellationToken) { try { @@ -1184,7 +1227,7 @@ internal static ComposeRunOutcome FromRunException(Exception ex, bool remapClien { /* #5016: whether an open timed out is not the driver's one shape (a read timeout, an expired budget, a connect, a pool wait, the GSS step's wrapper and a bare TimeoutException all differ), so the chain is walked in one helper. */ - return PostgresOpenTimeout.IsTimedOutOpen(open.InnerException!) + return PostgresOpenTimeout.IsTimedOutOpen(open.InnerException!) || open.FailedAfterTimeout ? ComposeRunOutcome.ServerError($"Error running query: could not get a store connection in time: {open.InnerException!.Message}") : ComposeRunOutcome.ServerError($"Error running query: could not open a store connection: {open.InnerException!.Message}"); } @@ -1226,7 +1269,8 @@ internal static ComposeRunOutcome FromPostgresException(PostgresException ex) => /// internal static async Task RunComposedPanelAsync( NpgsqlDataSource postgres, JsonObject body, System.Threading.CancellationToken cancellationToken, - ReadLatencyRecorder? readLatency = null, int clientDeadlineHeadroomSeconds = 0, bool remapClientTimeout = false, bool includeDataStartFields = false) + ReadLatencyRecorder? readLatency = null, int clientDeadlineHeadroomSeconds = 0, bool remapClientTimeout = false, bool includeDataStartFields = false, + Action? onRunException = null) { /* #4442 scope 2: recorded ONCE per call, here, so the web /api/compose/run route and the MCP run_custom_view_panel tool -- both of which call this ONE runner -- contribute exactly one @@ -1236,7 +1280,7 @@ run_custom_view_panel tool -- both of which call this ONE runner -- contribute e a bucket update is the only work in the try, and any failure there is swallowed and logged at Debug, exactly like the web loop's own recording. */ var stopwatch = Stopwatch.StartNew(); - var outcome = await RunComposedPanelCoreAsync(postgres, body, clientDeadlineHeadroomSeconds, remapClientTimeout, includeDataStartFields, cancellationToken, readLatency?.Logger); + var outcome = await RunComposedPanelCoreAsync(postgres, body, clientDeadlineHeadroomSeconds, remapClientTimeout, includeDataStartFields, cancellationToken, readLatency?.Logger, onRunException); RecordComposeLatency(readLatency, body, outcome, stopwatch.ElapsedMilliseconds, cancellationToken); return outcome; } @@ -1306,7 +1350,7 @@ the caller's own token already explains it. */ /// a failure it swallows. private static async Task RunComposedPanelCoreAsync( NpgsqlDataSource postgres, JsonObject body, int clientDeadlineHeadroomSeconds, bool remapClientTimeout, bool includeDataStartFields, System.Threading.CancellationToken cancellationToken, - ILogger? logger = null) + ILogger? logger = null, Action? onRunException = null) { if (body["panel"] is not JsonObject panel) { @@ -1498,6 +1542,8 @@ so a test can run it without a live Postgres round trip. */ } catch (Exception ex) when (ex is not OperationCanceledException) { + /* Test seam: the outcome keeps only the message, so a test that wants the chain gets it here. */ + onRunException?.Invoke(ex); return FromRunException(ex, remapClientTimeout); } } diff --git a/Darling/PerformanceMonitor.Darling.Service/PostgresOpenTimeout.cs b/Darling/PerformanceMonitor.Darling.Service/PostgresOpenTimeout.cs index 953c0c260b..3fac90c686 100644 --- a/Darling/PerformanceMonitor.Darling.Service/PostgresOpenTimeout.cs +++ b/Darling/PerformanceMonitor.Darling.Service/PostgresOpenTimeout.cs @@ -78,4 +78,37 @@ internal static bool IsTimedOutOpen(Exception exception) return false; } + + /// How much earlier than the configured Timeout a failure may land and still count as the timeout + /// (timer granularity and scheduling). + internal static readonly TimeSpan ClockSlack = TimeSpan.FromMilliseconds(100); + + /// + /// True when a driver failure came only after the open had used its whole Timeout. The driver's own timer can + /// tear the socket down under a read, so the failure surfaces as an over an aborted or + /// interrupted socket instead of a ; no shape rule sees that, but the clock does. A + /// anywhere in the chain (the server answered), a cancelled caller, or + /// a failure well before the timeout (refused, reset, closed, auth) is never a timed-out open. An + /// nested under the is not an exclusion: a + /// caller's cancellation never reaches this method and is covered by , so a nested one + /// with the caller still live is the driver's own Timeout timer firing under a read. Used beside + /// , not instead of it. + /// + internal static bool IsTimedOutByClock(Exception exception, TimeSpan elapsed, TimeSpan timeout, bool callerCancelled) + { + if (callerCancelled || exception is not NpgsqlException || timeout <= TimeSpan.Zero || elapsed + ClockSlack < timeout) + { + return false; + } + + for (var current = exception; current is not null; current = current.InnerException) + { + if (current is PostgresException) + { + return false; + } + } + + return true; + } }