From a024b1a866a962946a2cdb5da0dbc0b91a0a97d2 Mon Sep 17 00:00:00 2001 From: Andrew Armstrong Date: Thu, 11 Jun 2020 16:21:28 +1000 Subject: [PATCH] Added some additional exception detail information when encountering "InvalidOperationException: Concurrent reads or writes are not supported" as per https://github.com/StackExchange/StackExchange.Redis/issues/1438 --- src/StackExchange.Redis/PhysicalBridge.cs | 11 +++++++- src/StackExchange.Redis/PhysicalConnection.cs | 20 +++++++++++---- .../TemporaryDebugHelper.cs | 25 +++++++++++++++++++ 3 files changed, 50 insertions(+), 6 deletions(-) create mode 100644 src/StackExchange.Redis/TemporaryDebugHelper.cs diff --git a/src/StackExchange.Redis/PhysicalBridge.cs b/src/StackExchange.Redis/PhysicalBridge.cs index d1f2d2eff..fb6bd7376 100644 --- a/src/StackExchange.Redis/PhysicalBridge.cs +++ b/src/StackExchange.Redis/PhysicalBridge.cs @@ -733,9 +733,17 @@ internal WriteResult WriteMessageTakingWriteLockSync(PhysicalConnection physical if (result == WriteResult.Success) { + try + { #pragma warning disable CS0618 - result = physical.FlushSync(false, TimeoutMilliseconds); + result = physical.FlushSync(false, TimeoutMilliseconds); #pragma warning restore CS0618 + } + catch (InvalidOperationException ex) when (ex.Message.Contains("Concurrent reads or writes are not supported")) + { + // Throw with more detailed error information + throw TemporaryDebugHelper.CreateDetailedException($"{nameof(WriteMessageTakingWriteLockSync)}: token={token}, bridgeHashCode={GetHashCode()}, physicalConnectionHashCode={physical.GetHashCode()}", ex); + } } physical.SetIdle(); @@ -885,6 +893,7 @@ private void ProcessBacklog() if (result == WriteResult.Success) { _backlogStatus = BacklogStatus.Flushing; + #pragma warning disable CS0618 result = physical.FlushSync(false, timeout); #pragma warning restore CS0618 diff --git a/src/StackExchange.Redis/PhysicalConnection.cs b/src/StackExchange.Redis/PhysicalConnection.cs index bc77e3ac8..5b78cb3cb 100644 --- a/src/StackExchange.Redis/PhysicalConnection.cs +++ b/src/StackExchange.Redis/PhysicalConnection.cs @@ -888,6 +888,7 @@ void ThrowTimeout() #if DEBUG if (millisecondsTimeout > _maxFlushTime) _maxFlushTime = millisecondsTimeout; // a fair bet even if we didn't measure #endif + TemporaryDebugHelper.LastThrownFlushSyncTimeoutUtc = DateTime.UtcNow; throw new TimeoutException("timeout while synchronously flushing"); } } @@ -903,15 +904,24 @@ internal ValueTask FlushAsync(bool throwOnFailure) long flushBytes = -1; if (_ioPipe is SocketConnection sc) flushBytes = sc.GetCounters().BytesWaitingToBeSent; #endif - var flush = tmp.FlushAsync(); - if (!flush.IsCompletedSuccessfully) return FlushAsync_Awaited(this, flush, throwOnFailure + try + { + var flush = tmp.FlushAsync(); + if (!flush.IsCompletedSuccessfully) return FlushAsync_Awaited(this, flush, throwOnFailure #if DEBUG - , startFlush, flushBytes + , startFlush, flushBytes #endif - ); + ); #if DEBUG - RecordEndFlush(startFlush, flushBytes); + RecordEndFlush(startFlush, flushBytes); #endif + } + catch (InvalidOperationException ex) when (ex.Message.Contains("Concurrent reads or writes are not supported")) + { + // Throw with more detailed error information + throw TemporaryDebugHelper.CreateDetailedException($"{nameof(FlushAsync)}: tmp.GetHashCode()={tmp.GetHashCode()}, physicalConnectionHashCode:{GetHashCode()}", ex); + } + _writeStatus = WriteStatus.Flushed; UpdateLastWriteTime(); return new ValueTask(WriteResult.Success); diff --git a/src/StackExchange.Redis/TemporaryDebugHelper.cs b/src/StackExchange.Redis/TemporaryDebugHelper.cs new file mode 100644 index 000000000..ce43fcd5a --- /dev/null +++ b/src/StackExchange.Redis/TemporaryDebugHelper.cs @@ -0,0 +1,25 @@ +using System; + +namespace StackExchange.Redis +{ + /// + /// Temporary class to help debug an issue, see https://github.com/StackExchange/StackExchange.Redis/issues/1438 + /// + public static class TemporaryDebugHelper + { + /// + /// The last time a sync flush had timed out, if at all + /// + public static DateTime? LastThrownFlushSyncTimeoutUtc { get; set; } + + /// + /// Create a new error to be thrown with extra debugging information included in its message + /// + public static InvalidOperationException CreateDetailedException(string additionalErrorInformation, Exception innerException) + { + var lastTimedOutAgo = LastThrownFlushSyncTimeoutUtc != null ? DateTime.UtcNow - LastThrownFlushSyncTimeoutUtc.Value : (TimeSpan?) null; + + throw new InvalidOperationException($"Encountered error discussed on SE.Redis GitHub #1438 [{additionalErrorInformation} | LastThrownFlushSyncTimeoutUtc: {LastThrownFlushSyncTimeoutUtc} ({lastTimedOutAgo})]", innerException); + } + } +}