ILogger for ConnectionMultiplexer

Directory.Packages.props

@@ -12,6 +12,7 @@
     <PackageVersion Include="BenchmarkDotNet" Version="0.13.1" />
     <PackageVersion Include="GitHubActionsTestLogger" Version="1.3.0" />
     <PackageVersion Include="Microsoft.CodeAnalysis.PublicApiAnalyzers" Version="3.3.3" />
+    <PackageVersion Include="Microsoft.Extensions.Logging.Abstractions" Version="6.0.0" />
     <PackageVersion Include="Microsoft.NETFramework.ReferenceAssemblies" Version="1.0.2" />
     <PackageVersion Include="Microsoft.NET.Test.Sdk" Version="17.1.0" />
     <PackageVersion Include="Microsoft.SourceLink.GitHub" Version="1.1.1" />

src/StackExchange.Redis/ConfigurationOptions.cs

@@ -10,6 +10,7 @@
 using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 using StackExchange.Redis.Configuration;
 
 namespace StackExchange.Redis
@@ -159,6 +160,8 @@ public static string TryNormalize(string value)
 
         private BacklogPolicy backlogPolicy;
 
+        private ILogger logger;
+
         /// <summary>
         /// A LocalCertificateSelectionCallback delegate responsible for selecting the certificate used for authentication; note
         /// that this cannot be specified in the configuration-string.
@@ -410,6 +413,15 @@ public int KeepAlive
             set => keepAlive = value;
         }
 
+        /// <summary>
+        /// The <see cref="ILogger"/> to use for connection events.
+        /// </summary>
+        public ILogger Logger
+        {
+            get => logger;
+            set => logger = value;
+        }
+
         /// <summary>
         /// The user to use to authenticate with the server.
         /// </summary>

src/StackExchange.Redis/ConnectionMultiplexer.Sentinel.cs

@@ -349,7 +349,7 @@ internal void SwitchPrimary(EndPoint switchBlame, ConnectionMultiplexer connecti
     {
         if (log == null) log = TextWriter.Null;
 
-        using (var logProxy = LogProxy.TryCreate(log))
+        using (var logProxy = LogProxy.TryCreate(log, RawConfig))
         {
             string serviceName = connection.RawConfig.ServiceName;
 

src/StackExchange.Redis/EndPointCollection.cs

@@ -209,12 +209,12 @@ internal async Task ResolveEndPointsAsync(ConnectionMultiplexer multiplexer, Log
                         }
                         else
                         {
-                            log?.WriteLine($"Using DNS to resolve '{dns.Host}'...");
+                            log?.LogInfo($"Using DNS to resolve '{dns.Host}'...");
                             var ips = await Dns.GetHostAddressesAsync(dns.Host).ObserveErrors().ForAwait();
                             if (ips.Length == 1)
                             {
                                 ip = ips[0];
-                                log?.WriteLine($"'{dns.Host}' => {ip}");
+                                log?.LogInfo($"'{dns.Host}' => {ip}");
                                 cache[dns.Host] = ip;
                                 this[i] = new IPEndPoint(ip, dns.Port);
                             }
@@ -223,7 +223,7 @@ internal async Task ResolveEndPointsAsync(ConnectionMultiplexer multiplexer, Log
                     catch (Exception ex)
                     {
                         multiplexer.OnInternalError(ex);
-                        log?.WriteLine(ex.Message);
+                        log?.LogError(ex, ex.Message);
                     }
                 }
             }

src/StackExchange.Redis/ExceptionFactory.cs

@@ -1,6 +1,5 @@
 using System;
 using System.Collections.Generic;
-using System.Reflection;
 using System.Text;
 using System.Threading;
 
@@ -389,19 +388,5 @@ internal static Exception UnableToConnect(ConnectionMultiplexer muxer, string fa
 
             return new RedisConnectionException(ConnectionFailureType.UnableToConnect, sb.ToString());
         }
-
-        internal static Exception BeganProfilingWithDuplicateContext(object forContext)
-        {
-            var exc = new InvalidOperationException("Attempted to begin profiling for the same context twice");
-            exc.Data["forContext"] = forContext;
-            return exc;
-        }
-
-        internal static Exception FinishedProfilingWithInvalidContext(object forContext)
-        {
-            var exc = new InvalidOperationException("Attempted to finish profiling for a context which is no longer valid, or was never begun");
-            exc.Data["forContext"] = forContext;
-            return exc;
-        }
     }
 }

src/StackExchange.Redis/LogProxy.cs

@@ -1,50 +1,77 @@
 using System;
 using System.IO;
+using Microsoft.Extensions.Logging;
 
 namespace StackExchange.Redis;
 
 internal sealed class LogProxy : IDisposable
 {
-    public static LogProxy TryCreate(TextWriter writer)
-        => writer == null ? null : new LogProxy(writer);
+    public static LogProxy TryCreate(TextWriter writer, ConfigurationOptions options)
+        => writer == null && options?.Logger == null
+        ? null
+        : new LogProxy(writer, options?.Logger);
 
-    public override string ToString()
+    private TextWriter _log;
+    private ILogger _logger;
+    internal static Action<string> NullWriter = _ => { };
+    public object SyncLock => this;
+
+    private LogProxy(TextWriter log, ILogger logger)
     {
-        string s = null;
-        if (_log != null)
+        _log = log;
+        _logger = logger;
+    }
+
+    public void WriteLine()
+    {
+        if (_log != null) // note: double-checked
         {
             lock (SyncLock)
             {
-                s = _log?.ToString();
+                _log?.WriteLine();
             }
         }
-        return s ?? base.ToString();
     }
-    private TextWriter _log;
-    internal static Action<string> NullWriter = _ => { };
 
-    public object SyncLock => this;
-    private LogProxy(TextWriter log) => _log = log;
-    public void WriteLine()
+    public void LogInfo(string message = null)
     {
+        var msg = $"{DateTime.UtcNow:HH:mm:ss.ffff}: {message}";
         if (_log != null) // note: double-checked
         {
             lock (SyncLock)
             {
-                _log?.WriteLine();
+                _log?.WriteLine(msg);
+            }
+        }
+        _logger?.LogInformation(msg);
+    }
+
+    public void LogTrace(string message)
+    {
+        var msg = $"{DateTime.UtcNow:HH:mm:ss.ffff}: {message}";
+        if (_log != null) // note: double-checked
+        {
+            lock (SyncLock)
+            {
+                _log?.WriteLine(msg);
             }
         }
+        _logger?.LogTrace(msg);
     }
-    public void WriteLine(string message = null)
+
+    public void LogError(Exception ex, string message)
     {
+        var msg = $"{DateTime.UtcNow:HH:mm:ss.ffff}: {message}";
         if (_log != null) // note: double-checked
         {
             lock (SyncLock)
             {
-                _log?.WriteLine($"{DateTime.UtcNow:HH:mm:ss.ffff}: {message}");
+                _log?.WriteLine(msg);
             }
         }
+        _logger?.LogError(ex, msg);
     }
+
     public void WriteLine(string prefix, string message)
     {
         if (_log != null) // note: double-checked
@@ -55,11 +82,29 @@ public void WriteLine(string prefix, string message)
             }
         }
     }
+
+    public override string ToString()
+    {
+        string s = null;
+        if (_log != null)
+        {
+            lock (SyncLock)
+            {
+                s = _log?.ToString();
+            }
+        }
+        return s ?? base.ToString();
+    }
+
     public void Dispose()
     {
         if (_log != null) // note: double-checked
         {
-            lock (SyncLock) { _log = null; }
+            lock (SyncLock)
+            {
+                _log = null;
+            }
         }
+        _logger = null;
     }
 }

src/StackExchange.Redis/Message.cs

@@ -37,7 +37,7 @@ protected override void WriteImpl(PhysicalConnection physical)
             try
             {
                 var bridge = physical.BridgeCouldBeNull;
-                log?.WriteLine($"{bridge.Name}: Writing: {tail.CommandAndKey}");
+                log?.LogTrace($"{bridge.Name}: Writing: {tail.CommandAndKey}");
             }
             catch { }
             tail.WriteTo(physical);

src/StackExchange.Redis/PhysicalBridge.cs

@@ -6,6 +6,7 @@
 using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 #if !NETCOREAPP
 using Pipelines.Sockets.Unofficial.Threading;
 using static Pipelines.Sockets.Unofficial.Threading.MutexSlim;
@@ -384,7 +385,7 @@ internal async Task OnConnectedAsync(PhysicalConnection connection, LogProxy log
             if (physical == connection && !isDisposed && ChangeState(State.Connecting, State.ConnectedEstablishing))
             {
                 await ServerEndPoint.OnEstablishingAsync(connection, log).ForAwait();
-                log?.WriteLine($"{Format.ToString(ServerEndPoint)}: OnEstablishingAsync complete");
+                log?.LogInfo($"{Format.ToString(ServerEndPoint)}: OnEstablishingAsync complete");
             }
             else
             {
@@ -408,6 +409,7 @@ internal void ResetNonConnected()
 
         internal void OnConnectionFailed(PhysicalConnection connection, ConnectionFailureType failureType, Exception innerException)
         {
+            Multiplexer.RawConfig.Logger?.LogError(innerException, innerException.Message);
             Trace($"OnConnectionFailed: {connection}");
             // If we're configured to, fail all pending backlogged messages
             if (Multiplexer.RawConfig.BacklogPolicy?.AbortPendingOnConnectionFailure == true)
@@ -527,7 +529,9 @@ internal void OnHeartbeat(bool ifConnectedOnly)
                         if (shouldRetry)
                         {
                             Interlocked.Increment(ref connectTimeoutRetryCount);
-                            LastException = ExceptionFactory.UnableToConnect(Multiplexer, "ConnectTimeout");
+                            var ex = ExceptionFactory.UnableToConnect(Multiplexer, "ConnectTimeout");
+                            LastException = ex;
+                            Multiplexer.RawConfig.Logger?.LogError(ex, ex.Message);
                             Trace("Aborting connect");
                             // abort and reconnect
                             var snapshot = physical;
@@ -1291,7 +1295,7 @@ public PhysicalConnection TryConnect(LogProxy log)
                 {
                     if (!Multiplexer.IsDisposed)
                     {
-                        log?.WriteLine($"{Name}: Connecting...");
+                        log?.LogInfo($"{Name}: Connecting...");
                         Multiplexer.Trace("Connecting...", Name);
                         if (ChangeState(State.Disconnected, State.Connecting))
                         {
@@ -1308,7 +1312,7 @@ public PhysicalConnection TryConnect(LogProxy log)
                 }
                 catch (Exception ex)
                 {
-                    log?.WriteLine($"{Name}: Connect failed: {ex.Message}");
+                    log?.LogError(ex, $"{Name}: Connect failed: {ex.Message}");
                     Multiplexer.Trace("Connect failed: " + ex.Message, Name);
                     ChangeState(State.Disconnected);
                     OnInternalError(ex);

src/StackExchange.Redis/PhysicalConnection.cs

@@ -15,6 +15,7 @@
 using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 using Pipelines.Sockets.Unofficial;
 using Pipelines.Sockets.Unofficial.Arenas;
 
@@ -91,15 +92,15 @@ internal async Task BeginConnectAsync(LogProxy log)
             var endpoint = bridge?.ServerEndPoint?.EndPoint;
             if (endpoint == null)
             {
-                log?.WriteLine("No endpoint");
+                log?.LogError(new ArgumentNullException(nameof(endpoint)), "No endpoint");
                 return;
             }
 
             Trace("Connecting...");
             _socket = SocketManager.CreateSocket(endpoint);
             bridge.Multiplexer.RawConfig.BeforeSocketConnect?.Invoke(endpoint, bridge.ConnectionType, _socket);
             bridge.Multiplexer.OnConnecting(endpoint, bridge.ConnectionType);
-            log?.WriteLine($"{Format.ToString(endpoint)}: BeginConnectAsync");
+            log?.LogInfo($"{Format.ToString(endpoint)}: BeginConnectAsync");
 
             CancellationTokenSource timeoutSource = null;
             try
@@ -143,7 +144,7 @@ internal async Task BeginConnectAsync(LogProxy log)
                         }
                         else if (await ConnectedAsync(x, log, bridge.Multiplexer.SocketManager).ForAwait())
                         {
-                            log?.WriteLine($"{Format.ToString(endpoint)}: Starting read");
+                            log?.LogInfo($"{Format.ToString(endpoint)}: Starting read");
                             try
                             {
                                 StartReading();
@@ -161,9 +162,9 @@ internal async Task BeginConnectAsync(LogProxy log)
                             Shutdown();
                         }
                     }
-                    catch (ObjectDisposedException)
+                    catch (ObjectDisposedException ex)
                     {
-                        log?.WriteLine($"{Format.ToString(endpoint)}: (socket shutdown)");
+                        log?.LogError(ex, $"{Format.ToString(endpoint)}: (socket shutdown)");
                         try { RecordConnectionFailed(ConnectionFailureType.UnableToConnect, isInitialConnect: true); }
                         catch (Exception inner)
                         {
@@ -1400,7 +1401,7 @@ internal async ValueTask<bool> ConnectedAsync(Socket socket, LogProxy log, Socke
 
                 if (config.Ssl)
                 {
-                    log?.WriteLine("Configuring TLS");
+                    log?.LogInfo("Configuring TLS");
                     var host = config.SslHost;
                     if (string.IsNullOrWhiteSpace(host)) host = Format.ToStringHostOnly(bridge.ServerEndPoint.EndPoint);
 
@@ -1418,9 +1419,10 @@ internal async ValueTask<bool> ConnectedAsync(Socket socket, LogProxy log, Socke
                         {
                             Debug.WriteLine(ex.Message);
                             bridge.Multiplexer?.SetAuthSuspect();
+                            bridge.Multiplexer.RawConfig.Logger?.LogError(ex, ex.Message);
                             throw;
                         }
-                        log?.WriteLine($"TLS connection established successfully using protocol: {ssl.SslProtocol}");
+                        log?.LogInfo($"TLS connection established successfully using protocol: {ssl.SslProtocol}");
                     }
                     catch (AuthenticationException authexception)
                     {
@@ -1438,7 +1440,7 @@ internal async ValueTask<bool> ConnectedAsync(Socket socket, LogProxy log, Socke
 
                 _ioPipe = pipe;
 
-                log?.WriteLine($"{bridge?.Name}: Connected ");
+                log?.LogInfo($"{bridge?.Name}: Connected ");
 
                 await bridge.OnConnectedAsync(this, log).ForAwait();
                 return true;

src/StackExchange.Redis/PublicAPI.Shipped.txt

@@ -227,6 +227,8 @@ StackExchange.Redis.ConfigurationOptions.IncludePerformanceCountersInExceptions.
 StackExchange.Redis.ConfigurationOptions.IncludePerformanceCountersInExceptions.set -> void
 StackExchange.Redis.ConfigurationOptions.KeepAlive.get -> int
 StackExchange.Redis.ConfigurationOptions.KeepAlive.set -> void
+StackExchange.Redis.ConfigurationOptions.Logger.get -> Microsoft.Extensions.Logging.ILogger
+StackExchange.Redis.ConfigurationOptions.Logger.set -> void
 StackExchange.Redis.ConfigurationOptions.Password.get -> string
 StackExchange.Redis.ConfigurationOptions.Password.set -> void
 StackExchange.Redis.ConfigurationOptions.PreserveAsyncOrder.get -> bool

src/StackExchange.Redis/RedisServer.cs

@@ -330,7 +330,7 @@ public Task<DateTime> LastSaveAsync(CommandFlags flags = CommandFlags.None)
 
         public void MakeMaster(ReplicationChangeOptions options, TextWriter log = null)
         {
-            using (var proxy = LogProxy.TryCreate(log))
+            using (var proxy = LogProxy.TryCreate(log, multiplexer.RawConfig))
             {
                 // Do you believe in magic?
                 multiplexer.MakePrimaryAsync(server, options, proxy).Wait(60000);
@@ -339,7 +339,7 @@ public void MakeMaster(ReplicationChangeOptions options, TextWriter log = null)
 
         public async Task MakePrimaryAsync(ReplicationChangeOptions options, TextWriter log = null)
         {
-            using (var proxy = LogProxy.TryCreate(log))
+            using (var proxy = LogProxy.TryCreate(log, multiplexer.RawConfig))
             {
                 await multiplexer.MakePrimaryAsync(server, options, proxy);
             }