From 405f914e67a0790c93b5af12c3ec1f2e81f442eb Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Thu, 24 Jul 2025 16:27:35 +0300 Subject: [PATCH 1/2] chore: Replaces string interpolation with structured logging - PhysicalConnection & 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. --- src/StackExchange.Redis/LoggerExtensions.cs | 43 +++++++++++++++++++++ src/StackExchange.Redis/PhysicalBridge.cs | 16 ++++---- 2 files changed, 51 insertions(+), 8 deletions(-) diff --git a/src/StackExchange.Redis/LoggerExtensions.cs b/src/StackExchange.Redis/LoggerExtensions.cs index 3cb2ec6fb..d81df9c4a 100644 --- a/src/StackExchange.Redis/LoggerExtensions.cs +++ b/src/StackExchange.Redis/LoggerExtensions.cs @@ -579,4 +579,47 @@ 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); } diff --git a/src/StackExchange.Redis/PhysicalBridge.cs b/src/StackExchange.Redis/PhysicalBridge.cs index f5d75c188..34cef1f4b 100644 --- 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 LoggerExtensions.EndPointLogValue(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); From 9b2a38f69cf0304b499ac5e9dc1a8f8059cdb5e3 Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Thu, 24 Jul 2025 16:39:54 +0300 Subject: [PATCH 2/2] 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. --- src/StackExchange.Redis/LoggerExtensions.cs | 43 +++++++++++++++++++ src/StackExchange.Redis/PhysicalBridge.cs | 2 +- src/StackExchange.Redis/PhysicalConnection.cs | 16 +++---- 3 files changed, 52 insertions(+), 9 deletions(-) diff --git a/src/StackExchange.Redis/LoggerExtensions.cs b/src/StackExchange.Redis/LoggerExtensions.cs index d81df9c4a..759c3949b 100644 --- a/src/StackExchange.Redis/LoggerExtensions.cs +++ b/src/StackExchange.Redis/LoggerExtensions.cs @@ -622,4 +622,47 @@ internal static void LogWithThreadPoolStats(this ILogger? log, string message) 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 index 34cef1f4b..c430cf5af 100644 --- 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?.LogInformationOnEstablishingComplete(new LoggerExtensions.EndPointLogValue(ServerEndPoint.EndPoint)); + log?.LogInformationOnEstablishingComplete(new(ServerEndPoint.EndPoint)); } else { diff --git a/src/StackExchange.Redis/PhysicalConnection.cs b/src/StackExchange.Redis/PhysicalConnection.cs index 8a0bad393..324b952fd 100644 --- 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 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 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 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;