From 9fda7c56a866df814923f3dde2adb68c1957efc9 Mon Sep 17 00:00:00 2001 From: Nick Craver Date: Tue, 2 May 2023 11:09:21 -0400 Subject: [PATCH] Backlog timeout: include the time in message (#2452) One regression I just noticed in the exception message tweaks we did was we no longer readily include the timeout in the main message...but we should. Fixing messages and tests here. Before: > Exception: The message timed out in the backlog attempting to send because no connection became available - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts) After: > Exception: The message timed out in the backlog attempting to send because no connection became available **(100ms)** - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts) --- docs/ReleaseNotes.md | 1 + src/StackExchange.Redis/ExceptionFactory.cs | 1 + .../StackExchange.Redis.Tests/AbortOnConnectFailTests.cs | 8 ++++---- 3 files changed, 6 insertions(+), 4 deletions(-) diff --git a/docs/ReleaseNotes.md b/docs/ReleaseNotes.md index 9b39d48f3..e3bea8649 100644 --- a/docs/ReleaseNotes.md +++ b/docs/ReleaseNotes.md @@ -12,6 +12,7 @@ Current package versions: - Add: Support for `User`/`Password` in `DefaultOptionsProvider` to support token rotation scenarios ([#2445 by NickCraver](https://github.com/StackExchange/StackExchange.Redis/pull/2445)) - Fix [#2449](https://github.com/StackExchange/StackExchange.Redis/issues/2449): Resolve AOT trim warnings in `TryGetAzureRoleInstanceIdNoThrow` ([#2451 by eerhardt](https://github.com/StackExchange/StackExchange.Redis/pull/2451)) - Adds: Support for `HTTP/1.1 200 Connection established` in HTTP Tunnel ([#2448 by flobernd](https://github.com/StackExchange/StackExchange.Redis/pull/2448)) +- Adds: Timeout duration to backlog timeout error messages ([#2452 by NickCraver](https://github.com/StackExchange/StackExchange.Redis/pull/2452)) ## 2.6.104 diff --git a/src/StackExchange.Redis/ExceptionFactory.cs b/src/StackExchange.Redis/ExceptionFactory.cs index 05a47b5c9..4308b4f00 100644 --- a/src/StackExchange.Redis/ExceptionFactory.cs +++ b/src/StackExchange.Redis/ExceptionFactory.cs @@ -235,6 +235,7 @@ internal static Exception Timeout(ConnectionMultiplexer multiplexer, string? bas // If we're in the situation where we've never connected if (logConnectionException && lastConnectionException is not null) { + sb.Append(" (").Append(Format.ToString(multiplexer.TimeoutMilliseconds)).Append("ms)"); sb.Append(" - Last Connection Exception: ").Append(lastConnectionException.Message); } diff --git a/tests/StackExchange.Redis.Tests/AbortOnConnectFailTests.cs b/tests/StackExchange.Redis.Tests/AbortOnConnectFailTests.cs index 49138c535..0ba8fca9e 100644 --- a/tests/StackExchange.Redis.Tests/AbortOnConnectFailTests.cs +++ b/tests/StackExchange.Redis.Tests/AbortOnConnectFailTests.cs @@ -49,11 +49,11 @@ public void DisconnectAndReconnectThrowsConnectionExceptionSync() var server = conn.GetServerSnapshot()[0]; server.SimulateConnectionFailure(SimulatedFailureType.All); - // Exception: The message timed out in the backlog attempting to send because no connection became available - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts) + // Exception: The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts) var ex = Assert.ThrowsAny(() => db.Ping()); Log("Exception: " + ex.Message); Assert.True(ex is RedisConnectionException or RedisTimeoutException); - Assert.StartsWith("The message timed out in the backlog attempting to send because no connection became available - Last Connection Exception: ", ex.Message); + Assert.StartsWith("The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: ", ex.Message); Assert.NotNull(ex.InnerException); var iex = Assert.IsType(ex.InnerException); Assert.Contains(iex.Message, ex.Message); @@ -73,10 +73,10 @@ public async Task DisconnectAndNoReconnectThrowsConnectionExceptionAsync() var server = conn.GetServerSnapshot()[0]; server.SimulateConnectionFailure(SimulatedFailureType.All); - // Exception: The message timed out in the backlog attempting to send because no connection became available - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts) + // Exception: The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts) var ex = await Assert.ThrowsAsync(() => db.PingAsync()); Log("Exception: " + ex.Message); - Assert.StartsWith("The message timed out in the backlog attempting to send because no connection became available - Last Connection Exception: ", ex.Message); + Assert.StartsWith("The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: ", ex.Message); Assert.NotNull(ex.InnerException); var iex = Assert.IsType(ex.InnerException); Assert.Contains(iex.Message, ex.Message);