Custom view panels say a silent store's open timed out, whatever the driver wraps the timeout in, and the open-timeout test names the exception chain when it fails

Darling/Darling.Tests/ComposeClientTimeoutAttributionTests.cs

@@ -231,4 +231,16 @@
     {
         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<NpgsqlConnection> 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);
+    }
 }

Darling/Darling.Tests/ComposeOpenPhaseTimeoutTests.cs

@@ -102,6 +102,28 @@ public void Dispose()
         }
     }
 
+    /// <summary>Every level of the chain the compose runner caught: type, message, and the socket code or HResult that
+    /// says what the operating system did.</summary>
+    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);
     }

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));
+    }
 }

Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs

@@ -1140,6 +1140,13 @@ internal ComposeStoreOpenException(Exception inner)
             : base(inner.Message, inner)
         {
         }
+
+        /// <summary>True when the open failed with a driver exception only after the connection <c>Timeout</c> had elapsed
+        /// (see <see cref="PostgresOpenTimeout.IsTimedOutByClock"/>), whatever shape the driver wrapped the failure in.</summary>
+        internal bool FailedAfterTimeout { get; init; }
+
+        /// <summary>The driver exception this wraps, for classification only (never for answer text).</summary>
+        internal Exception Cause => InnerException!;
     }
 
     /// <summary>Opens a compose runner's store connection, before any statement runs. An <see cref="NpgsqlException"/>
@@ -1148,6 +1155,42 @@ internal ComposeStoreOpenException(Exception inner)
     /// <see cref="ComposeStoreOpenException"/>. A cancellation propagates unchanged: it is the caller's.</summary>
     private static async Task<NpgsqlConnection> 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;
+        }
+    }
+
+    /// <summary>The data source's open <c>Timeout</c>, 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.</summary>
+    private static TimeSpan OpenTimeoutOrZero(NpgsqlDataSource postgres)
+    {
+        try
+        {
+            return TimeSpan.FromSeconds(new NpgsqlConnectionStringBuilder(postgres.ConnectionString).Timeout);
+        }
+        catch (ArgumentException)
+        {
+            return TimeSpan.Zero;
+        }
+    }
+
+    private static async Task<NpgsqlConnection> 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) =>
     /// </summary>
     internal static async Task<ComposeRunOutcome> 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<Exception>? 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.</summary>
     private static async Task<ComposeRunOutcome> RunComposedPanelCoreAsync(
         NpgsqlDataSource postgres, JsonObject body, int clientDeadlineHeadroomSeconds, bool remapClientTimeout, bool includeDataStartFields, System.Threading.CancellationToken cancellationToken,
-        ILogger? logger = null)
+        ILogger? logger = null, Action<Exception>? 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);
         }
     }

Darling/PerformanceMonitor.Darling.Service/PostgresOpenTimeout.cs

@@ -78,4 +78,37 @@ internal static bool IsTimedOutOpen(Exception exception)
 
         return false;
     }
+
+    /// <summary>How much earlier than the configured <c>Timeout</c> a failure may land and still count as the timeout
+    /// (timer granularity and scheduling).</summary>
+    internal static readonly TimeSpan ClockSlack = TimeSpan.FromMilliseconds(100);
+
+    /// <summary>
+    /// True when a driver failure came only after the open had used its whole <c>Timeout</c>. The driver's own timer can
+    /// tear the socket down under a read, so the failure surfaces as an <see cref="NpgsqlException"/> over an aborted or
+    /// interrupted socket instead of a <see cref="TimeoutException"/>; no shape rule sees that, but the clock does. A
+    /// <see cref="PostgresException"/> 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
+    /// <see cref="OperationCanceledException"/> nested under the <see cref="NpgsqlException"/> is not an exclusion: a
+    /// caller's cancellation never reaches this method and is covered by <paramref name="callerCancelled"/>, so a nested one
+    /// with the caller still live is the driver's own <c>Timeout</c> timer firing under a read. Used beside
+    /// <see cref="IsTimedOutOpen"/>, not instead of it.
+    /// </summary>
+    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;
+    }
 }