Exceptions: add timeout info everywhere

Note: this doesn't include command and key, which is still behind the IncludeDetailInExceptions flag

StackExchange.Redis/ConnectionMultiplexer.cs

@@ -2089,7 +2089,7 @@ internal Exception GetException(WriteResult result, Message message, ServerEndPo
                     }
                     catch { }
 
-                    return ExceptionFactory.Timeout(IncludeDetailInExceptions, "The timeout was reached before the message could be written to the output buffer, and it was not sent ("
+                    return ExceptionFactory.Timeout(this, "The timeout was reached before the message could be written to the output buffer, and it was not sent ("
                         + Format.ToString(TimeoutMilliseconds) + "ms" + counters + ")", message, server);
                 case WriteResult.WriteFailure:
                 default:
@@ -2146,71 +2146,7 @@ internal T ExecuteSyncImpl<T>(Message message, ResultProcessor<T> processor, Ser
                     {
                         Trace("Timeout performing " + message);
                         Interlocked.Increment(ref syncTimeouts);
-                        string errMessage;
-                        List<Tuple<string, string>> data = null;
-                        if (server == null || !IncludeDetailInExceptions)
-                        {
-                            errMessage = "Timeout performing " + message.Command.ToString();
-                        }
-                        else
-                        {
-                            var sb = new StringBuilder("Timeout performing ").Append(message.CommandAndKey).Append(" (").Append(Format.ToString(TimeoutMilliseconds)).Append("ms)");
-                            data = new List<Tuple<string, string>> { Tuple.Create("Message", message.CommandAndKey) };
-                            void add(string lk, string sk, string v)
-                            {
-                                if (v != null)
-                                {
-                                    data.Add(Tuple.Create(lk, v));
-                                    sb.Append(", ").Append(sk).Append(": ").Append(v);
-                                }
-                            }
-
-                            server.GetOutstandingCount(message.Command, out int inst, out int qs, out int @in);
-                            add("Instantaneous", "inst", inst.ToString());
-                            add("Queue-Awaiting-Response", "qs", qs.ToString());
-                            add("Inbound-Bytes", "in", @in.ToString());
-                            add("Manager", "mgr", SocketManager?.GetState());
-
-                            add("Client-Name", "clientName", ClientName);
-                            add("Server-Endpoint", "serverEndpoint", server.EndPoint.ToString());
-                            var hashSlot = message.GetHashSlot(ServerSelectionStrategy);
-                            // only add keyslot if its a valid cluster key slot
-                            if (hashSlot != ServerSelectionStrategy.NoSlot)
-                            {
-                                add("Key-HashSlot", "PerfCounterHelperkeyHashSlot", message.GetHashSlot(this.ServerSelectionStrategy).ToString());
-                            }
-                            int busyWorkerCount = PerfCounterHelper.GetThreadPoolStats(out string iocp, out string worker);
-                            add("ThreadPool-IO-Completion", "IOCP", iocp);
-                            add("ThreadPool-Workers", "WORKER", worker);
-                            data.Add(Tuple.Create("Busy-Workers", busyWorkerCount.ToString()));
-
-                            if (IncludePerformanceCountersInExceptions)
-                            {
-                                add("Local-CPU", "Local-CPU", PerfCounterHelper.GetSystemCpuPercent());
-                            }
-
-                            sb.Append(" (Please take a look at this article for some common client-side issues that can cause timeouts: ");
-                            sb.Append(timeoutHelpLink);
-                            sb.Append(")");
-                            errMessage = sb.ToString();
-                            if (StormLogThreshold >= 0 && qs >= StormLogThreshold && Interlocked.CompareExchange(ref haveStormLog, 1, 0) == 0)
-                            {
-                                var log = server.GetStormLog(message.Command);
-                                if (string.IsNullOrWhiteSpace(log)) Interlocked.Exchange(ref haveStormLog, 0);
-                                else Interlocked.Exchange(ref stormLogSnapshot, log);
-                            }
-                        }
-                        var timeoutEx = ExceptionFactory.Timeout(IncludeDetailInExceptions, errMessage, message, server);
-                        timeoutEx.HelpLink = timeoutHelpLink;
-
-                        if (data != null)
-                        {
-                            foreach (var kv in data)
-                            {
-                                timeoutEx.Data["Redis-" + kv.Item1] = kv.Item2;
-                            }
-                        }
-                        throw timeoutEx;
+                        throw ExceptionFactory.Timeout(this, "Timeout performing " + message.Command.ToString(), message, server);
                         // very important not to return "source" to the pool here
                     }
                 }
@@ -2232,8 +2168,8 @@ void add(string lk, string sk, string v)
         /// </summary>
         public bool IncludePerformanceCountersInExceptions { get; set; }
 
-        private int haveStormLog = 0;
-        private string stormLogSnapshot;
+        internal int haveStormLog = 0;
+        internal string stormLogSnapshot;
         /// <summary>
         /// Limit at which to start recording unusual busy patterns (only one log will be retained at a time;
         /// set to a negative value to disable this feature)

StackExchange.Redis/ExceptionFactory.cs

 using System;
 using System.Collections.Generic;
 using System.Text;
+using System.Threading;
 
 namespace StackExchange.Redis
 {
@@ -9,7 +10,8 @@ internal static class ExceptionFactory
         private const string
             DataCommandKey = "redis-command",
             DataSentStatusKey = "request-sent-status",
-            DataServerKey = "redis-server";
+            DataServerKey = "redis-server",
+            timeoutHelpLink = "https://stackexchange.github.io/StackExchange.Redis/Timeouts";
 
         internal static Exception AdminModeNotEnabled(bool includeDetail, RedisCommand command, Message message, ServerEndPoint server)
         {
@@ -165,10 +167,79 @@ internal static Exception NoCursor(RedisCommand command)
             return new RedisCommandException("Command cannot be used with a cursor: " + s);
         }
 
-        internal static Exception Timeout(bool includeDetail, string errorMessage, Message message, ServerEndPoint server)
+        internal static Exception Timeout(ConnectionMultiplexer mutiplexer, string baseErrorMessage, Message message, ServerEndPoint server)
         {
-            var ex = new RedisTimeoutException(errorMessage, message?.Status ?? CommandStatus.Unknown);
-            if (includeDetail) AddDetail(ex, message, server, null);
+            List<Tuple<string, string>> data = new List<Tuple<string, string>> { Tuple.Create("Message", message.CommandAndKey) };
+            var sb = new StringBuilder();
+            if (!string.IsNullOrEmpty(baseErrorMessage))
+            {
+                sb.Append(baseErrorMessage);
+            }
+            else
+            {
+                sb.Append("Timeout performing ").Append(message.CommandAndKey).Append(" (").Append(Format.ToString(mutiplexer.TimeoutMilliseconds)).Append("ms)");
+            }
+
+            void add(string lk, string sk, string v)
+            {
+                if (v != null)
+                {
+                    data.Add(Tuple.Create(lk, v));
+                    sb.Append(", ").Append(sk).Append(": ").Append(v);
+                }
+            }
+
+            if (server != null)
+            {
+                server.GetOutstandingCount(message.Command, out int inst, out int qs, out int @in);
+                add("Instantaneous", "inst", inst.ToString());
+                add("Queue-Awaiting-Response", "qs", qs.ToString());
+                add("Inbound-Bytes", "in", @in.ToString());
+
+                if (mutiplexer.StormLogThreshold >= 0 && qs >= mutiplexer.StormLogThreshold && Interlocked.CompareExchange(ref mutiplexer.haveStormLog, 1, 0) == 0)
+                {
+                    var log = server.GetStormLog(message.Command);
+                    if (string.IsNullOrWhiteSpace(log)) Interlocked.Exchange(ref mutiplexer.haveStormLog, 0);
+                    else Interlocked.Exchange(ref mutiplexer.stormLogSnapshot, log);
+                }
+                add("Server-Endpoint", "serverEndpoint", server.EndPoint.ToString());
+            }
+            add("Manager", "mgr", mutiplexer.SocketManager?.GetState());
+
+            add("Client-Name", "clientName", mutiplexer.ClientName);
+            var hashSlot = message.GetHashSlot(mutiplexer.ServerSelectionStrategy);
+            // only add keyslot if its a valid cluster key slot
+            if (hashSlot != ServerSelectionStrategy.NoSlot)
+            {
+                add("Key-HashSlot", "PerfCounterHelperkeyHashSlot", message.GetHashSlot(mutiplexer.ServerSelectionStrategy).ToString());
+            }
+            int busyWorkerCount = PerfCounterHelper.GetThreadPoolStats(out string iocp, out string worker);
+            add("ThreadPool-IO-Completion", "IOCP", iocp);
+            add("ThreadPool-Workers", "WORKER", worker);
+            data.Add(Tuple.Create("Busy-Workers", busyWorkerCount.ToString()));
+
+            if (mutiplexer.IncludePerformanceCountersInExceptions)
+            {
+                add("Local-CPU", "Local-CPU", PerfCounterHelper.GetSystemCpuPercent());
+            }
+
+            sb.Append(" (Please take a look at this article for some common client-side issues that can cause timeouts: ");
+            sb.Append(timeoutHelpLink);
+            sb.Append(")");
+
+            var ex = new RedisTimeoutException(sb.ToString(), message?.Status ?? CommandStatus.Unknown)
+            {
+                HelpLink = timeoutHelpLink
+            };
+            if (data != null)
+            {
+                foreach (var kv in data)
+                {
+                    ex.Data["Redis-" + kv.Item1] = kv.Item2;
+                }
+            }
+
+            if (mutiplexer.IncludeDetailInExceptions) AddDetail(ex, message, server, null);
             return ex;
         }
 

StackExchange.Redis/PhysicalConnection.cs

@@ -575,14 +575,13 @@ internal void OnBridgeHeartbeat()
                     var bridge = BridgeCouldBeNull;
                     if (bridge == null) return;
 
-                    bool includeDetail = bridge.Multiplexer.IncludeDetailInExceptions;
                     var server = bridge?.ServerEndPoint;
                     var timeout = bridge.Multiplexer.AsyncTimeoutMilliseconds;
                     foreach (var msg in _writtenAwaitingResponse)
                     {
                         if (msg.HasAsyncTimedOut(now, timeout, out var elapsed))
                         {
-                            var timeoutEx = ExceptionFactory.Timeout(includeDetail, $"Timeout awaiting response ({elapsed}ms elapsed, timeout is {timeout}ms)", msg, server);
+                            var timeoutEx = ExceptionFactory.Timeout(bridge.Multiplexer, $"Timeout awaiting response ({elapsed}ms elapsed, timeout is {timeout}ms)", msg, server);
                             bridge.Multiplexer?.OnMessageFaulted(msg, timeoutEx);
                             msg.SetExceptionAndComplete(timeoutEx, bridge); // tell the message that it is doomed
                             bridge.Multiplexer.OnAsyncTimeout();

StackExchange.Redis/RedisBase.cs

@@ -172,10 +172,11 @@ protected ScanResult GetNextPageSync(IScanningCursor obj, long cursor)
                 return redis.ExecuteSync(CreateMessage(cursor), Processor, server);
             }
 
-            protected Task<ScanResult> GetNextPageAsync(IScanningCursor obj, long cursor)
+            protected Task<ScanResult> GetNextPageAsync(IScanningCursor obj, long cursor, out Message message)
             {
                 activeCursor = obj;
-                return redis.ExecuteAsync(CreateMessage(cursor), Processor, server);
+                message = CreateMessage(cursor);
+                return redis.ExecuteAsync(message, Processor, server);
             }
 
             protected bool TryWait(Task<ScanResult> pending) => redis.TryWait(pending);
@@ -197,8 +198,11 @@ public CursorEnumerator(CursorEnumerable<T> parent)
 
                 private void LoadNextPageAsync()
                 {
-                    if(pending == null && nextCursor != 0)
-                        pending = parent.GetNextPageAsync(this, nextCursor);
+                    if (pending == null && nextCursor != 0)
+                    {
+                        pending = parent.GetNextPageAsync(this, nextCursor, out var message);
+                        pendingMessage = message;
+                    }
                 }
 
                 private bool SimpleNext()
@@ -214,6 +218,7 @@ private bool SimpleNext()
 
                 private T[] page;
                 private Task<ScanResult> pending;
+                private Message pendingMessage;
                 private int pageIndex;
                 private long currentCursor, nextCursor;
 
@@ -233,6 +238,7 @@ private void ProcessReply(ScanResult result)
                     pageIndex = -1;
                     page = result.Values;
                     pending = null;
+                    pendingMessage = null;
                 }
 
                 public bool MoveNext()
@@ -260,7 +266,7 @@ public bool MoveNext()
                                 }
                                 else
                                 {
-                                    throw ExceptionFactory.Timeout(parent.redis.multiplexer.IncludeDetailInExceptions, "Timeout waiting for scan cursor to complete", null, parent.server);
+                                    throw ExceptionFactory.Timeout(parent.redis.multiplexer, null, pendingMessage, parent.server);
                                 }
 
                                 if (SimpleNext()) return true;
@@ -290,6 +296,7 @@ public void Reset()
                     state = State.Initial;
                     page = null;
                     pending = null;
+                    pendingMessage = null;
                 }
 
                 long IScanningCursor.Cursor => currentCursor;