Counters: add sync-ops, async-ops, and how long a server has been connected (#2300)

More info to help us advise and debug timeouts for users! 

Overall adds for timeout messages:
- `Sync-Ops`: A count of synchronous operation calls
- `Async-Ops`: A count of asynchronous operation calls
- `Server-Connected-Seconds`: How long the bridge in question has been connected ("n/a" if not connected)

Author: NickCraver

docs/ReleaseNotes.md

@@ -11,6 +11,7 @@ Current package versions:
 - Fix [#1520](https://github.com/StackExchange/StackExchange.Redis/issues/1520) & [#1660](https://github.com/StackExchange/StackExchange.Redis/issues/1660): When `MOVED` is encountered from a cluster, a reconfigure will happen proactively to react to cluster changes ASAP ([#2286 by NickCraver](https://github.com/StackExchange/StackExchange.Redis/pull/2286))
 - Fix [#2249](https://github.com/StackExchange/StackExchange.Redis/issues/2249): Properly handle a `fail` state (new `ClusterNode.IsFail` property) for `CLUSTER NODES` and expose `fail?` as a property (`IsPossiblyFail`) as well ([#2288 by NickCraver](https://github.com/StackExchange/StackExchange.Redis/pull/2288))
 - Adds: `IConnectionMultiplexer.ServerMaintenanceEvent` (was on `ConnectionMultiplexer` but not the interface) ([#2306 by NickCraver](https://github.com/StackExchange/StackExchange.Redis/pull/2306))
+- Adds: To timeout messages, additional debug information: `Sync-Ops` (synchronous operations), `Async-Ops` (asynchronous operations), and `Server-Connected-Seconds` (how long the connection in question has been connected, or `"n/a"`) ([#2300 by NickCraver](https://github.com/StackExchange/StackExchange.Redis/pull/2300))
 
 
 ## 2.6.80

src/StackExchange.Redis/ConnectionMultiplexer.cs

@@ -31,6 +31,7 @@ public sealed partial class ConnectionMultiplexer : IInternalConnectionMultiplex
         /// Tracks overall connection multiplexer counts.
         /// </summary>
         internal int _connectAttemptCount = 0, _connectCompletedCount = 0, _connectionCloseCount = 0;
+        internal long syncOps, asyncOps;
         private long syncTimeouts, fireAndForgets, asyncTimeouts;
         private string? failureMessage, activeConfigCause;
         private IDisposable? pulse;
@@ -1867,6 +1868,8 @@ internal static void ThrowFailed<T>(TaskCompletionSource<T>? source, Exception u
                 return defaultValue;
             }
 
+            Interlocked.Increment(ref syncOps);
+
             if (message.IsFireAndForget)
             {
 #pragma warning disable CS0618 // Type or member is obsolete
@@ -1929,6 +1932,8 @@ static async Task<T> ExecuteAsyncImpl_Awaited(ConnectionMultiplexer @this, Value
                 return CompletedTask<T>.FromDefault(defaultValue, state);
             }
 
+            Interlocked.Increment(ref asyncOps);
+
             TaskCompletionSource<T>? tcs = null;
             IResultBox<T>? source = null;
             if (!message.IsFireAndForget)
@@ -1978,6 +1983,8 @@ static async Task<T> ExecuteAsyncImpl_Awaited(ConnectionMultiplexer @this, Value
                 return CompletedTask<T?>.Default(state);
             }
 
+            Interlocked.Increment(ref asyncOps);
+
             TaskCompletionSource<T?>? tcs = null;
             IResultBox<T?>? source = null;
             if (!message.IsFireAndForget)

src/StackExchange.Redis/ExceptionFactory.cs

@@ -1,6 +1,5 @@
 using System;
 using System.Collections.Generic;
-using System.Reflection;
 using System.Security.Authentication;
 using System.Text;
 using System.Threading;
@@ -323,13 +322,17 @@ private static void AddCommonDetail(
                 Add(data, sb, "Last-Result-Bytes", "last-in", bs.Connection.BytesLastResult.ToString());
                 Add(data, sb, "Inbound-Buffer-Bytes", "cur-in", bs.Connection.BytesInBuffer.ToString());
 
+                Add(data, sb, "Sync-Ops", "sync-ops", multiplexer.syncOps.ToString());
+                Add(data, sb, "Async-Ops", "async-ops", multiplexer.asyncOps.ToString());
+
                 if (multiplexer.StormLogThreshold >= 0 && bs.Connection.MessagesSentAwaitingResponse >= multiplexer.StormLogThreshold && Interlocked.CompareExchange(ref multiplexer.haveStormLog, 1, 0) == 0)
                 {
                     var log = server.GetStormLog(message);
                     if (string.IsNullOrWhiteSpace(log)) Interlocked.Exchange(ref multiplexer.haveStormLog, 0);
                     else Interlocked.Exchange(ref multiplexer.stormLogSnapshot, log);
                 }
                 Add(data, sb, "Server-Endpoint", "serverEndpoint", (server.EndPoint.ToString() ?? "Unknown").Replace("Unspecified/", ""));
+                Add(data, sb, "Server-Connected-Seconds", "conn-sec", bs.ConnectedAt is DateTime dt ? (DateTime.UtcNow - dt).TotalSeconds.ToString("0.##") : "n/a");
             }
             Add(data, sb, "Multiplexer-Connects", "mc", $"{multiplexer._connectAttemptCount}/{multiplexer._connectCompletedCount}/{multiplexer._connectionCloseCount}");
             Add(data, sb, "Manager", "mgr", multiplexer.SocketManager?.GetState());

src/StackExchange.Redis/PhysicalBridge.cs

@@ -66,6 +66,7 @@ internal sealed class PhysicalBridge : IDisposable
 #endif
 
         internal string? PhysicalName => physical?.ToString();
+        public DateTime? ConnectedAt { get; private set; }
 
         public PhysicalBridge(ServerEndPoint serverEndPoint, ConnectionType type, int timeoutMilliseconds)
         {
@@ -265,6 +266,10 @@ internal readonly struct BridgeStatus
             /// </summary>
             public int MessagesSinceLastHeartbeat { get; init; }
             /// <summary>
+            /// The time this connection was connected at, if it's connected currently.
+            /// </summary>
+            public DateTime? ConnectedAt { get; init; }
+            /// <summary>
             /// Whether the pipe writer is currently active.
             /// </summary>
             public bool IsWriterActive { get; init; }
@@ -298,12 +303,13 @@ internal readonly struct BridgeStatus
             public static BridgeStatus Zero { get; } = new() { Connection = PhysicalConnection.ConnectionStatus.Zero };
 
             public override string ToString() =>
-                $"MessagesSinceLastHeartbeat: {MessagesSinceLastHeartbeat}, Writer: {(IsWriterActive ? "Active" : "Inactive")}, BacklogStatus: {BacklogStatus}, BacklogMessagesPending: (Queue: {BacklogMessagesPending}, Counter: {BacklogMessagesPendingCounter}), TotalBacklogMessagesQueued: {TotalBacklogMessagesQueued}, Connection: ({Connection})";
+                $"MessagesSinceLastHeartbeat: {MessagesSinceLastHeartbeat}, ConnectedAt: {ConnectedAt?.ToString("u") ?? "n/a"}, Writer: {(IsWriterActive ? "Active" : "Inactive")}, BacklogStatus: {BacklogStatus}, BacklogMessagesPending: (Queue: {BacklogMessagesPending}, Counter: {BacklogMessagesPendingCounter}), TotalBacklogMessagesQueued: {TotalBacklogMessagesQueued}, Connection: ({Connection})";
         }
 
         internal BridgeStatus GetStatus() => new()
         {
             MessagesSinceLastHeartbeat = (int)(Interlocked.Read(ref operationCount) - Interlocked.Read(ref profileLastLog)),
+            ConnectedAt = ConnectedAt,
 #if NETCOREAPP
             IsWriterActive = _singleWriterMutex.CurrentCount == 0,
 #else
@@ -385,6 +391,7 @@ internal async Task OnConnectedAsync(PhysicalConnection connection, LogProxy? lo
             Trace("OnConnected");
             if (physical == connection && !isDisposed && ChangeState(State.Connecting, State.ConnectedEstablishing))
             {
+                ConnectedAt ??= DateTime.UtcNow;
                 await ServerEndPoint.OnEstablishingAsync(connection, log).ForAwait();
                 log?.WriteLine($"{Format.ToString(ServerEndPoint)}: OnEstablishingAsync complete");
             }
@@ -431,6 +438,7 @@ internal void OnDisconnected(ConnectionFailureType failureType, PhysicalConnecti
             Trace($"OnDisconnected: {failureType}");
 
             oldState = default(State); // only defined when isCurrent = true
+            ConnectedAt = default;
             if (isCurrent = (physical == connection))
             {
                 Trace("Bridge noting disconnect from active connection" + (isDisposed ? " (disposed)" : ""));

tests/BasicTest/BasicTest.csproj

@@ -2,7 +2,7 @@
 
   <PropertyGroup>
     <Description>StackExchange.Redis.BasicTest .NET Core</Description>
-    <TargetFrameworks>net472;net5.0</TargetFrameworks>
+    <TargetFrameworks>net472;net6.0</TargetFrameworks>
     <AssemblyName>BasicTest</AssemblyName>
     <OutputType>Exe</OutputType>
     <PackageId>BasicTest</PackageId>

tests/BasicTestBaseline/BasicTestBaseline.csproj

@@ -2,7 +2,7 @@
 
   <PropertyGroup>
     <Description>StackExchange.Redis.BasicTest .NET Core</Description>
-    <TargetFrameworks>net472;net5.0</TargetFrameworks>
+    <TargetFrameworks>net472;net6.0</TargetFrameworks>
     <AssemblyName>BasicTestBaseline</AssemblyName>
     <OutputType>Exe</OutputType>
     <PackageId>BasicTestBaseline</PackageId>

tests/StackExchange.Redis.Tests/ExceptionFactoryTests.cs

@@ -121,6 +121,9 @@ public void TimeoutException()
             Assert.Contains("serverEndpoint: " + server.EndPoint, ex.Message);
             Assert.Contains("IOCP: ", ex.Message);
             Assert.Contains("WORKER: ", ex.Message);
+            Assert.Contains("sync-ops: ", ex.Message);
+            Assert.Contains("async-ops: ", ex.Message);
+            Assert.Contains("conn-sec: n/a", ex.Message);
 #if NETCOREAPP
                 Assert.Contains("POOL: ", ex.Message);
 #endif

tests/StackExchange.Redis.Tests/SentinelTests.cs

@@ -451,8 +451,12 @@ public async Task SentinelGetSentinelAddressesTest()
     public async Task ReadOnlyConnectionReplicasTest()
     {
         var replicas = SentinelServerA.SentinelGetReplicaAddresses(ServiceName);
-        var config = new ConfigurationOptions();
+        if (replicas.Length == 0)
+        {
+            Skip.Inconclusive("Sentinel race: 0 replicas to test against.");
+        }
 
+        var config = new ConfigurationOptions();
         foreach (var replica in replicas)
         {
             config.EndPoints.Add(replica);

toys/KestrelRedisServer/KestrelRedisServer.csproj

@@ -1,7 +1,7 @@
 <Project Sdk="Microsoft.NET.Sdk.Web">
 
   <PropertyGroup>
-    <TargetFramework>net5.0</TargetFramework>
+    <TargetFramework>net6.0</TargetFramework>
     <NoWarn>$(NoWarn);CS1591</NoWarn>
   </PropertyGroup>
 

toys/TestConsole/TestConsole.csproj

@@ -2,7 +2,7 @@
 
   <PropertyGroup>
     <OutputType>Exe</OutputType>
-    <TargetFrameworks>net50;net472</TargetFrameworks>
+    <TargetFrameworks>net6.0;net472</TargetFrameworks>
     <DefineConstants>SEV2</DefineConstants>
     <AutoGenerateBindingRedirects>true</AutoGenerateBindingRedirects>
   </PropertyGroup>