From 4a13caf4b126d149e549cf6a0f6893a93de6ba4b Mon Sep 17 00:00:00 2001 From: Nick Craver Date: Mon, 30 Oct 2023 10:47:02 -0400 Subject: [PATCH] Logging: fix race in disposal of a passed-in TextWriter (#2581) Occasionally we'd see `chunkLength` errors from `StringWriter` `.ToString()` calls after connecting. I think we've isolated this (via test stress runs) down to a write happening post-lock on the `TextWriterLogger` disposal. This lock in dispose ensures we're not trying to write to a writer we should have fully released at the end of a `.Connect()`/`.ConnectAsync()` call. --- .../ConnectionMultiplexer.cs | 4 +-- src/StackExchange.Redis/TextWriterLogger.cs | 25 +++++++++++++------ 2 files changed, 20 insertions(+), 9 deletions(-) diff --git a/src/StackExchange.Redis/ConnectionMultiplexer.cs b/src/StackExchange.Redis/ConnectionMultiplexer.cs index 8f50b7fbc..44cc9f7c7 100644 --- a/src/StackExchange.Redis/ConnectionMultiplexer.cs +++ b/src/StackExchange.Redis/ConnectionMultiplexer.cs @@ -638,7 +638,7 @@ private static async Task ConnectImplAsync(ConfigurationO { if (connectHandler != null && muxer != null) muxer.ConnectionFailed -= connectHandler; if (killMe != null) try { killMe.Dispose(); } catch { } - if (log is TextWriterLogger twLogger) twLogger.Dispose(); + if (log is TextWriterLogger twLogger) twLogger.Release(); } } @@ -740,7 +740,7 @@ private static ConnectionMultiplexer ConnectImpl(ConfigurationOptions configurat { if (connectHandler != null && muxer != null) muxer.ConnectionFailed -= connectHandler; if (killMe != null) try { killMe.Dispose(); } catch { } - if (log is TextWriterLogger twLogger) twLogger.Dispose(); + if (log is TextWriterLogger twLogger) twLogger.Release(); } } diff --git a/src/StackExchange.Redis/TextWriterLogger.cs b/src/StackExchange.Redis/TextWriterLogger.cs index 4a4a99fd4..0582b70d3 100644 --- a/src/StackExchange.Redis/TextWriterLogger.cs +++ b/src/StackExchange.Redis/TextWriterLogger.cs @@ -4,10 +4,10 @@ namespace StackExchange.Redis; -internal sealed class TextWriterLogger : ILogger, IDisposable +internal sealed class TextWriterLogger : ILogger { private TextWriter? _writer; - private ILogger? _wrapped; + private readonly ILogger? _wrapped; internal static Action NullWriter = _ => { }; @@ -26,16 +26,27 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except { lock (writer) { - writer.Write($"{DateTime.UtcNow:HH:mm:ss.ffff}: "); - writer.WriteLine(formatter(state, exception)); + // We check here again because it's possible we've released below, and never want to write past releasing. + if (_writer is TextWriter innerWriter) + { + innerWriter.Write($"{DateTime.UtcNow:HH:mm:ss.ffff}: "); + innerWriter.WriteLine(formatter(state, exception)); + } } } } - public void Dispose() + public void Release() { - _writer = null; - _wrapped = null; + // We lock here because we may have piled up on a lock above and still be writing. + // We never want a write to go past the Release(), as many TextWriter implementations are not thread safe. + if (_writer is TextWriter writer) + { + lock (writer) + { + _writer = null; + } + } } }