Skip to content

Commit

Permalink
Logging: fix race in disposal of a passed-in TextWriter (#2581)
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
NickCraver authored Oct 30, 2023
1 parent 5504ed9 commit 4a13caf
Show file tree
Hide file tree
Showing 2 changed files with 20 additions and 9 deletions.
4 changes: 2 additions & 2 deletions src/StackExchange.Redis/ConnectionMultiplexer.cs
Original file line number Diff line number Diff line change
Expand Up @@ -638,7 +638,7 @@ private static async Task<ConnectionMultiplexer> 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();
}
}

Expand Down Expand Up @@ -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();
}
}

Expand Down
25 changes: 18 additions & 7 deletions src/StackExchange.Redis/TextWriterLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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<string> NullWriter = _ => { };

Expand All @@ -26,16 +26,27 @@ public void Log<TState>(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;
}
}
}
}

Expand Down

0 comments on commit 4a13caf

Please sign in to comment.