chore: Replaces string interpolation with structured logging - PhysicalConnection & PhysicalBridge (#2929)

Meir017 · web-flow · commit b3aeb61ff3b8 · 2025-07-24T14:52:39.000+01:00
* chore: Replaces string interpolation with structured logging - PhysicalConnection &amp; PhysicalBridge

Replaces string interpolation with structured logging

Migrates logging calls from string interpolation to structured logging using LoggerMessage attributes. This improves performance by avoiding string allocation and enables better log analysis through structured data.

Adds new logging extension methods for PhysicalBridge operations including connection establishment, failures, dead socket detection, and resurrection attempts.

* Replaces manual logging with structured logger methods

Introduces dedicated LoggerMessage attributes for PhysicalConnection operations to improve logging performance and consistency.

Replaces string interpolation and manual log calls with strongly-typed logging methods that provide better compile-time safety and runtime performance through source generation.

Covers connection lifecycle events including endpoint validation, connection attempts, TLS configuration, socket operations, and connection establishment.
diff --git a/src/StackExchange.Redis/LoggerExtensions.cs b/src/StackExchange.Redis/LoggerExtensions.cs
@@ -579,4 +579,90 @@ internal static void LogWithThreadPoolStats(this ILogger? log, string message)
         EventId = 86,
         Message = "{Server}: Auto-configured (HELLO) role: {Role}")]
     internal static partial void LogInformationAutoConfiguredHelloRole(this ILogger logger, ServerEndPointLogValue server, string role);
+
+    // PhysicalBridge logging methods
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 87,
+        Message = "{EndPoint}: OnEstablishingAsync complete")]
+    internal static partial void LogInformationOnEstablishingComplete(this ILogger logger, EndPointLogValue endPoint);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 88,
+        Message = "{ErrorMessage}")]
+    internal static partial void LogInformationConnectionFailureRequested(this ILogger logger, Exception exception, string errorMessage);
+
+    [LoggerMessage(
+        Level = LogLevel.Error,
+        EventId = 89,
+        Message = "{ErrorMessage}")]
+    internal static partial void LogErrorConnectionIssue(this ILogger logger, Exception exception, string errorMessage);
+
+    [LoggerMessage(
+        Level = LogLevel.Warning,
+        EventId = 90,
+        Message = "Dead socket detected, no reads in {LastReadSecondsAgo} seconds with {TimeoutCount} timeouts, issuing disconnect")]
+    internal static partial void LogWarningDeadSocketDetected(this ILogger logger, long lastReadSecondsAgo, long timeoutCount);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 91,
+        Message = "Resurrecting {Bridge} (retry: {RetryCount})")]
+    internal static partial void LogInformationResurrecting(this ILogger logger, PhysicalBridge bridge, long retryCount);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 92,
+        Message = "{BridgeName}: Connecting...")]
+    internal static partial void LogInformationConnecting(this ILogger logger, string bridgeName);
+
+    [LoggerMessage(
+        Level = LogLevel.Error,
+        EventId = 93,
+        Message = "{BridgeName}: Connect failed: {ErrorMessage}")]
+    internal static partial void LogErrorConnectFailed(this ILogger logger, Exception exception, string bridgeName, string errorMessage);
+
+    // PhysicalConnection logging methods
+    [LoggerMessage(
+        Level = LogLevel.Error,
+        EventId = 94,
+        Message = "No endpoint")]
+    internal static partial void LogErrorNoEndpoint(this ILogger logger, Exception exception);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 95,
+        Message = "{EndPoint}: BeginConnectAsync")]
+    internal static partial void LogInformationBeginConnectAsync(this ILogger logger, EndPointLogValue endPoint);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 96,
+        Message = "{EndPoint}: Starting read")]
+    internal static partial void LogInformationStartingRead(this ILogger logger, EndPointLogValue endPoint);
+
+    [LoggerMessage(
+        Level = LogLevel.Error,
+        EventId = 97,
+        Message = "{EndPoint}: (socket shutdown)")]
+    internal static partial void LogErrorSocketShutdown(this ILogger logger, Exception exception, EndPointLogValue endPoint);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 98,
+        Message = "Configuring TLS")]
+    internal static partial void LogInformationConfiguringTLS(this ILogger logger);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 99,
+        Message = "TLS connection established successfully using protocol: {SslProtocol}")]
+    internal static partial void LogInformationTLSConnectionEstablished(this ILogger logger, System.Security.Authentication.SslProtocols sslProtocol);
+
+    [LoggerMessage(
+        Level = LogLevel.Information,
+        EventId = 100,
+        Message = "{BridgeName}: Connected")]
+    internal static partial void LogInformationConnected(this ILogger logger, string bridgeName);
 }
diff --git a/src/StackExchange.Redis/PhysicalBridge.cs b/src/StackExchange.Redis/PhysicalBridge.cs
@@ -431,7 +431,7 @@ internal async Task OnConnectedAsync(PhysicalConnection connection, ILogger? log
             {
                 ConnectedAt ??= DateTime.UtcNow;
                 await ServerEndPoint.OnEstablishingAsync(connection, log).ForAwait();
-                log?.LogInformation($"{Format.ToString(ServerEndPoint)}: OnEstablishingAsync complete");
+                log?.LogInformationOnEstablishingComplete(new(ServerEndPoint.EndPoint));
             }
             else
             {
@@ -457,11 +457,11 @@ internal void OnConnectionFailed(PhysicalConnection connection, ConnectionFailur
         {
             if (wasRequested)
             {
-                Multiplexer.Logger?.LogInformation(innerException, innerException.Message);
+                Multiplexer.Logger?.LogInformationConnectionFailureRequested(innerException, innerException.Message);
             }
             else
             {
-                Multiplexer.Logger?.LogError(innerException, innerException.Message);
+                Multiplexer.Logger?.LogErrorConnectionIssue(innerException, innerException.Message);
             }
             Trace($"OnConnectionFailed: {connection}");
             // If we're configured to, fail all pending backlogged messages
@@ -589,7 +589,7 @@ internal void OnHeartbeat(bool ifConnectedOnly)
                             Interlocked.Increment(ref connectTimeoutRetryCount);
                             var ex = ExceptionFactory.UnableToConnect(Multiplexer, "ConnectTimeout", Name);
                             LastException = ex;
-                            Multiplexer.Logger?.LogError(ex, ex.Message);
+                            Multiplexer.Logger?.LogErrorConnectionIssue(ex, ex.Message);
                             Trace("Aborting connect");
                             // abort and reconnect
                             var snapshot = physical;
@@ -671,7 +671,7 @@ internal void OnHeartbeat(bool ifConnectedOnly)
                                 // This is meant to address the scenario we see often in Linux configs where TCP retries will happen for 15 minutes.
                                 // To us as a client, we'll see the socket as green/open/fine when writing but we'll bet getting nothing back.
                                 // Since we can't depend on the pipe to fail in that case, we want to error here based on the criteria above so we reconnect broken clients much faster.
-                                tmp.BridgeCouldBeNull?.Multiplexer.Logger?.LogWarning($"Dead socket detected, no reads in {tmp.LastReadSecondsAgo} seconds with {timedOutThisHeartbeat} timeouts, issuing disconnect");
+                                tmp.BridgeCouldBeNull?.Multiplexer.Logger?.LogWarningDeadSocketDetected(tmp.LastReadSecondsAgo, timedOutThisHeartbeat);
                                 OnDisconnected(ConnectionFailureType.SocketFailure, tmp, out _, out State oldState);
                                 tmp.Dispose(); // Cleanup the existing connection/socket if any, otherwise it will wait reading indefinitely
                             }
@@ -691,7 +691,7 @@ internal void OnHeartbeat(bool ifConnectedOnly)
                             // Increment count here, so that we don't re-enter in Connecting case up top - we don't want to re-enter and log there.
                             Interlocked.Increment(ref connectTimeoutRetryCount);
 
-                            Multiplexer.Logger?.LogInformation($"Resurrecting {ToString()} (retry: {connectTimeoutRetryCount})");
+                            Multiplexer.Logger?.LogInformationResurrecting(this, connectTimeoutRetryCount);
                             Multiplexer.OnResurrecting(ServerEndPoint.EndPoint, ConnectionType);
                             TryConnect(null);
                         }
@@ -1453,7 +1453,7 @@ private bool ChangeState(State oldState, State newState)
                 {
                     if (!Multiplexer.IsDisposed)
                     {
-                        log?.LogInformation($"{Name}: Connecting...");
+                        log?.LogInformationConnecting(Name);
                         Multiplexer.Trace("Connecting...", Name);
                         if (ChangeState(State.Disconnected, State.Connecting))
                         {
@@ -1470,7 +1470,7 @@ private bool ChangeState(State oldState, State newState)
                 }
                 catch (Exception ex)
                 {
-                    log?.LogError(ex, $"{Name}: Connect failed: {ex.Message}");
+                    log?.LogErrorConnectFailed(ex, Name, ex.Message);
                     Multiplexer.Trace("Connect failed: " + ex.Message, Name);
                     ChangeState(State.Disconnected);
                     OnInternalError(ex);
diff --git a/src/StackExchange.Redis/PhysicalConnection.cs b/src/StackExchange.Redis/PhysicalConnection.cs
@@ -109,7 +109,7 @@ internal async Task BeginConnectAsync(ILogger? log)
             var endpoint = bridge?.ServerEndPoint?.EndPoint;
             if (bridge == null || endpoint == null)
             {
-                log?.LogError(new ArgumentNullException(nameof(endpoint)), "No endpoint");
+                log?.LogErrorNoEndpoint(new ArgumentNullException(nameof(endpoint)));
                 return;
             }
 
@@ -135,7 +135,7 @@ internal async Task BeginConnectAsync(ILogger? log)
                 }
             }
             bridge.Multiplexer.OnConnecting(endpoint, bridge.ConnectionType);
-            log?.LogInformation($"{Format.ToString(endpoint)}: BeginConnectAsync");
+            log?.LogInformationBeginConnectAsync(new(endpoint));
 
             CancellationTokenSource? timeoutSource = null;
             try
@@ -184,7 +184,7 @@ internal async Task BeginConnectAsync(ILogger? log)
                         }
                         else if (await ConnectedAsync(x, log, bridge.Multiplexer.SocketManager!).ForAwait())
                         {
-                            log?.LogInformation($"{Format.ToString(endpoint)}: Starting read");
+                            log?.LogInformationStartingRead(new(endpoint));
                             try
                             {
                                 StartReading();
@@ -204,7 +204,7 @@ internal async Task BeginConnectAsync(ILogger? log)
                     }
                     catch (ObjectDisposedException ex)
                     {
-                        log?.LogError(ex, $"{Format.ToString(endpoint)}: (socket shutdown)");
+                        log?.LogErrorSocketShutdown(ex, new(endpoint));
                         try { RecordConnectionFailed(ConnectionFailureType.UnableToConnect, isInitialConnect: true); }
                         catch (Exception inner)
                         {
@@ -1563,7 +1563,7 @@ internal async ValueTask<bool> ConnectedAsync(Socket? socket, ILogger? log, Sock
 
                 if (config.Ssl)
                 {
-                    log?.LogInformation("Configuring TLS");
+                    log?.LogInformationConfiguringTLS();
                     var host = config.SslHost;
                     if (host.IsNullOrWhiteSpace())
                     {
@@ -1599,10 +1599,10 @@ internal async ValueTask<bool> ConnectedAsync(Socket? socket, ILogger? log, Sock
                         {
                             Debug.WriteLine(ex.Message);
                             bridge.Multiplexer.SetAuthSuspect(ex);
-                            bridge.Multiplexer.Logger?.LogError(ex, ex.Message);
+                            bridge.Multiplexer.Logger?.LogErrorConnectionIssue(ex, ex.Message);
                             throw;
                         }
-                        log?.LogInformation($"TLS connection established successfully using protocol: {ssl.SslProtocol}");
+                        log?.LogInformationTLSConnectionEstablished(ssl.SslProtocol);
                     }
                     catch (AuthenticationException authexception)
                     {
@@ -1625,7 +1625,7 @@ internal async ValueTask<bool> ConnectedAsync(Socket? socket, ILogger? log, Sock
 
                 _ioPipe = pipe;
 
-                log?.LogInformation($"{bridge.Name}: Connected ");
+                log?.LogInformationConnected(bridge.Name);
 
                 await bridge.OnConnectedAsync(this, log).ForAwait();
                 return true;

Original file line number	Diff line number	Diff line change
`@@ -431,7 +431,7 @@ internal async Task OnConnectedAsync(PhysicalConnection connection, ILogger? log`
`431`	`431`	`{`
`432`	`432`	`ConnectedAt ??= DateTime.UtcNow;`
`433`	`433`	`await ServerEndPoint.OnEstablishingAsync(connection, log).ForAwait();`
`434`		`- log?.LogInformation($"{Format.ToString(ServerEndPoint)}: OnEstablishingAsync complete");`
	`434`	`+ log?.LogInformationOnEstablishingComplete(new(ServerEndPoint.EndPoint));`
`435`	`435`	`}`
`436`	`436`	`else`
`437`	`437`	`{`
`@@ -457,11 +457,11 @@ internal void OnConnectionFailed(PhysicalConnection connection, ConnectionFailur`
`457`	`457`	`{`
`458`	`458`	`if (wasRequested)`
`459`	`459`	`{`
`460`		`- Multiplexer.Logger?.LogInformation(innerException, innerException.Message);`
	`460`	`+ Multiplexer.Logger?.LogInformationConnectionFailureRequested(innerException, innerException.Message);`
`461`	`461`	`}`
`462`	`462`	`else`
`463`	`463`	`{`
`464`		`- Multiplexer.Logger?.LogError(innerException, innerException.Message);`
	`464`	`+ Multiplexer.Logger?.LogErrorConnectionIssue(innerException, innerException.Message);`
`465`	`465`	`}`
`466`	`466`	`Trace($"OnConnectionFailed: {connection}");`
`467`	`467`	`// If we're configured to, fail all pending backlogged messages`
`@@ -589,7 +589,7 @@ internal void OnHeartbeat(bool ifConnectedOnly)`
`589`	`589`	`Interlocked.Increment(ref connectTimeoutRetryCount);`
`590`	`590`	`var ex = ExceptionFactory.UnableToConnect(Multiplexer, "ConnectTimeout", Name);`
`591`	`591`	`LastException = ex;`
`592`		`- Multiplexer.Logger?.LogError(ex, ex.Message);`
	`592`	`+ Multiplexer.Logger?.LogErrorConnectionIssue(ex, ex.Message);`
`593`	`593`	`Trace("Aborting connect");`
`594`	`594`	`// abort and reconnect`
`595`	`595`	`var snapshot = physical;`
`@@ -671,7 +671,7 @@ internal void OnHeartbeat(bool ifConnectedOnly)`
`671`	`671`	`// This is meant to address the scenario we see often in Linux configs where TCP retries will happen for 15 minutes.`
`672`	`672`	`// To us as a client, we'll see the socket as green/open/fine when writing but we'll bet getting nothing back.`
`673`	`673`	`// Since we can't depend on the pipe to fail in that case, we want to error here based on the criteria above so we reconnect broken clients much faster.`
`674`		`- tmp.BridgeCouldBeNull?.Multiplexer.Logger?.LogWarning($"Dead socket detected, no reads in {tmp.LastReadSecondsAgo} seconds with {timedOutThisHeartbeat} timeouts, issuing disconnect");`
	`674`	`+ tmp.BridgeCouldBeNull?.Multiplexer.Logger?.LogWarningDeadSocketDetected(tmp.LastReadSecondsAgo, timedOutThisHeartbeat);`
`675`	`675`	`OnDisconnected(ConnectionFailureType.SocketFailure, tmp, out _, out State oldState);`
`676`	`676`	`tmp.Dispose(); // Cleanup the existing connection/socket if any, otherwise it will wait reading indefinitely`
`677`	`677`	`}`
`@@ -691,7 +691,7 @@ internal void OnHeartbeat(bool ifConnectedOnly)`
`691`	`691`	`// Increment count here, so that we don't re-enter in Connecting case up top - we don't want to re-enter and log there.`
`692`	`692`	`Interlocked.Increment(ref connectTimeoutRetryCount);`
`693`	`693`
`694`		`- Multiplexer.Logger?.LogInformation($"Resurrecting {ToString()} (retry: {connectTimeoutRetryCount})");`
	`694`	`+ Multiplexer.Logger?.LogInformationResurrecting(this, connectTimeoutRetryCount);`
`695`	`695`	`Multiplexer.OnResurrecting(ServerEndPoint.EndPoint, ConnectionType);`
`696`	`696`	`TryConnect(null);`
`697`	`697`	`}`
`@@ -1453,7 +1453,7 @@ private bool ChangeState(State oldState, State newState)`
`1453`	`1453`	`{`
`1454`	`1454`	`if (!Multiplexer.IsDisposed)`
`1455`	`1455`	`{`
`1456`		`- log?.LogInformation($"{Name}: Connecting...");`
	`1456`	`+ log?.LogInformationConnecting(Name);`
`1457`	`1457`	`Multiplexer.Trace("Connecting...", Name);`
`1458`	`1458`	`if (ChangeState(State.Disconnected, State.Connecting))`
`1459`	`1459`	`{`
`@@ -1470,7 +1470,7 @@ private bool ChangeState(State oldState, State newState)`
`1470`	`1470`	`}`
`1471`	`1471`	`catch (Exception ex)`
`1472`	`1472`	`{`
`1473`		`- log?.LogError(ex, $"{Name}: Connect failed: {ex.Message}");`
	`1473`	`+ log?.LogErrorConnectFailed(ex, Name, ex.Message);`
`1474`	`1474`	`Multiplexer.Trace("Connect failed: " + ex.Message, Name);`
`1475`	`1475`	`ChangeState(State.Disconnected);`
`1476`	`1476`	`OnInternalError(ex);`
Original file line number	Diff line number	Diff line change
`@@ -109,7 +109,7 @@ internal async Task BeginConnectAsync(ILogger? log)`
`109`	`109`	`var endpoint = bridge?.ServerEndPoint?.EndPoint;`
`110`	`110`	`if (bridge == null \|\| endpoint == null)`
`111`	`111`	`{`
`112`		`- log?.LogError(new ArgumentNullException(nameof(endpoint)), "No endpoint");`
	`112`	`+ log?.LogErrorNoEndpoint(new ArgumentNullException(nameof(endpoint)));`
`113`	`113`	`return;`
`114`	`114`	`}`
`115`	`115`
`@@ -135,7 +135,7 @@ internal async Task BeginConnectAsync(ILogger? log)`
`135`	`135`	`}`
`136`	`136`	`}`
`137`	`137`	`bridge.Multiplexer.OnConnecting(endpoint, bridge.ConnectionType);`
`138`		`- log?.LogInformation($"{Format.ToString(endpoint)}: BeginConnectAsync");`
	`138`	`+ log?.LogInformationBeginConnectAsync(new(endpoint));`
`139`	`139`
`140`	`140`	`CancellationTokenSource? timeoutSource = null;`
`141`	`141`	`try`
`@@ -184,7 +184,7 @@ internal async Task BeginConnectAsync(ILogger? log)`
`184`	`184`	`}`
`185`	`185`	`else if (await ConnectedAsync(x, log, bridge.Multiplexer.SocketManager!).ForAwait())`
`186`	`186`	`{`
`187`		`- log?.LogInformation($"{Format.ToString(endpoint)}: Starting read");`
	`187`	`+ log?.LogInformationStartingRead(new(endpoint));`
`188`	`188`	`try`
`189`	`189`	`{`
`190`	`190`	`StartReading();`
`@@ -204,7 +204,7 @@ internal async Task BeginConnectAsync(ILogger? log)`
`204`	`204`	`}`
`205`	`205`	`catch (ObjectDisposedException ex)`
`206`	`206`	`{`
`207`		`- log?.LogError(ex, $"{Format.ToString(endpoint)}: (socket shutdown)");`
	`207`	`+ log?.LogErrorSocketShutdown(ex, new(endpoint));`
`208`	`208`	`try { RecordConnectionFailed(ConnectionFailureType.UnableToConnect, isInitialConnect: true); }`
`209`	`209`	`catch (Exception inner)`
`210`	`210`	`{`
`@@ -1563,7 +1563,7 @@ internal async ValueTask<bool> ConnectedAsync(Socket? socket, ILogger? log, Sock`
`1563`	`1563`
`1564`	`1564`	`if (config.Ssl)`
`1565`	`1565`	`{`
`1566`		`- log?.LogInformation("Configuring TLS");`
	`1566`	`+ log?.LogInformationConfiguringTLS();`
`1567`	`1567`	`var host = config.SslHost;`
`1568`	`1568`	`if (host.IsNullOrWhiteSpace())`
`1569`	`1569`	`{`
`@@ -1599,10 +1599,10 @@ internal async ValueTask<bool> ConnectedAsync(Socket? socket, ILogger? log, Sock`
`1599`	`1599`	`{`
`1600`	`1600`	`Debug.WriteLine(ex.Message);`
`1601`	`1601`	`bridge.Multiplexer.SetAuthSuspect(ex);`
`1602`		`- bridge.Multiplexer.Logger?.LogError(ex, ex.Message);`
	`1602`	`+ bridge.Multiplexer.Logger?.LogErrorConnectionIssue(ex, ex.Message);`
`1603`	`1603`	`throw;`
`1604`	`1604`	`}`
`1605`		`- log?.LogInformation($"TLS connection established successfully using protocol: {ssl.SslProtocol}");`
	`1605`	`+ log?.LogInformationTLSConnectionEstablished(ssl.SslProtocol);`
`1606`	`1606`	`}`
`1607`	`1607`	`catch (AuthenticationException authexception)`
`1608`	`1608`	`{`
`@@ -1625,7 +1625,7 @@ internal async ValueTask<bool> ConnectedAsync(Socket? socket, ILogger? log, Sock`
`1625`	`1625`
`1626`	`1626`	`_ioPipe = pipe;`
`1627`	`1627`
`1628`		`- log?.LogInformation($"{bridge.Name}: Connected ");`
	`1628`	`+ log?.LogInformationConnected(bridge.Name);`
`1629`	`1629`
`1630`	`1630`	`await bridge.OnConnectedAsync(this, log).ForAwait();`
`1631`	`1631`	`return true;`