From fb357bae191de2193ec087250b53ec0fb5bed9ba Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Wed, 23 Jul 2025 12:31:30 +0300 Subject: [PATCH 1/2] chore: Replaces string interpolation with structured logging Migrates Redis server endpoint logging from string interpolation to LoggerMessage attributes for better performance and structured logging support. Adds 14 new LoggerMessage methods for server connection lifecycle events including handshake, authentication, configuration, and buffer operations. Uses ServerEndPointLogValue wrapper to ensure consistent server representation in logs while maintaining type safety. --- src/StackExchange.Redis/LoggerExtensions.cs | 85 +++++++++++++++++++++ src/StackExchange.Redis/ServerEndPoint.cs | 28 +++---- 2 files changed, 99 insertions(+), 14 deletions(-) diff --git a/src/StackExchange.Redis/LoggerExtensions.cs b/src/StackExchange.Redis/LoggerExtensions.cs index af57264bb..69fc1a7db 100644 --- a/src/StackExchange.Redis/LoggerExtensions.cs +++ b/src/StackExchange.Redis/LoggerExtensions.cs @@ -403,4 +403,89 @@ internal static void LogWithThreadPoolStats(this ILogger? log, string message) EventId = 56, Message = "...but we did find instead: {DeDottedEndpoint}")] internal static partial void LogInformationFoundAlternativeEndpoint(this ILogger logger, string deDottedEndpoint); + + // ServerEndPoint logging methods + [LoggerMessage( + Level = LogLevel.Information, + EventId = 57, + Message = "{Server}: OnConnectedAsync already connected start")] + internal static partial void LogInformationOnConnectedAsyncAlreadyConnectedStart(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 58, + Message = "{Server}: OnConnectedAsync already connected end")] + internal static partial void LogInformationOnConnectedAsyncAlreadyConnectedEnd(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 59, + Message = "{Server}: OnConnectedAsync init (State={ConnectionState})")] + internal static partial void LogInformationOnConnectedAsyncInit(this ILogger logger, ServerEndPointLogValue server, PhysicalBridge.State? connectionState); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 60, + Message = "{Server}: OnConnectedAsync completed ({Result})")] + internal static partial void LogInformationOnConnectedAsyncCompleted(this ILogger logger, ServerEndPointLogValue server, string result); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 61, + Message = "{Server}: Auto-configuring...")] + internal static partial void LogInformationAutoConfiguring(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 62, + Message = "{EndPoint}: Requesting tie-break (Key=\"{TieBreakerKey}\")...")] + internal static partial void LogInformationRequestingTieBreak(this ILogger logger, EndPointLogValue endPoint, string tieBreakerKey); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 63, + Message = "{Server}: Server handshake")] + internal static partial void LogInformationServerHandshake(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 64, + Message = "{Server}: Authenticating via HELLO")] + internal static partial void LogInformationAuthenticatingViaHello(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 65, + Message = "{Server}: Authenticating (user/password)")] + internal static partial void LogInformationAuthenticatingUserPassword(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 66, + Message = "{Server}: Authenticating (password)")] + internal static partial void LogInformationAuthenticatingPassword(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 67, + Message = "{Server}: Setting client name: {ClientName}")] + internal static partial void LogInformationSettingClientName(this ILogger logger, ServerEndPointLogValue server, string clientName); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 68, + Message = "{Server}: Setting client lib/ver")] + internal static partial void LogInformationSettingClientLibVer(this ILogger logger, ServerEndPointLogValue server); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 69, + Message = "{Server}: Sending critical tracer (handshake): {CommandAndKey}")] + internal static partial void LogInformationSendingCriticalTracer(this ILogger logger, ServerEndPointLogValue server, string commandAndKey); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = 70, + Message = "{Server}: Flushing outbound buffer")] + internal static partial void LogInformationFlushingOutboundBuffer(this ILogger logger, ServerEndPointLogValue server); } diff --git a/src/StackExchange.Redis/ServerEndPoint.cs b/src/StackExchange.Redis/ServerEndPoint.cs index 1e32275d6..96b6bcc5a 100644 --- a/src/StackExchange.Redis/ServerEndPoint.cs +++ b/src/StackExchange.Redis/ServerEndPoint.cs @@ -116,7 +116,7 @@ public Task OnConnectedAsync(ILogger? log = null, bool sendTracerIfConne { async Task IfConnectedAsync(ILogger? log, bool sendTracerIfConnected, bool autoConfigureIfConnected) { - log?.LogInformation($"{Format.ToString(this)}: OnConnectedAsync already connected start"); + log?.LogInformationOnConnectedAsyncAlreadyConnectedStart(new(this)); if (autoConfigureIfConnected) { await AutoConfigureAsync(null, log).ForAwait(); @@ -125,15 +125,15 @@ async Task IfConnectedAsync(ILogger? log, bool sendTracerIfConnected, bo { await SendTracerAsync(log).ForAwait(); } - log?.LogInformation($"{Format.ToString(this)}: OnConnectedAsync already connected end"); + log?.LogInformationOnConnectedAsyncAlreadyConnectedEnd(new(this)); return "Already connected"; } if (!IsConnected) { - log?.LogInformation($"{Format.ToString(this)}: OnConnectedAsync init (State={interactive?.ConnectionState})"); + log?.LogInformationOnConnectedAsyncInit(new(this), interactive?.ConnectionState); var tcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - _ = tcs.Task.ContinueWith(t => log?.LogInformation($"{Format.ToString(this)}: OnConnectedAsync completed ({t.Result})")); + _ = tcs.Task.ContinueWith(t => log?.LogInformationOnConnectedAsyncCompleted(new(this), t.Result)); lock (_pendingConnectionMonitors) { _pendingConnectionMonitors.Add(tcs); @@ -383,7 +383,7 @@ internal async Task AutoConfigureAsync(PhysicalConnection? connection, ILogger? return; } - log?.LogInformation($"{Format.ToString(this)}: Auto-configuring..."); + log?.LogInformationAutoConfiguring(new(this)); var commandMap = Multiplexer.CommandMap; const CommandFlags flags = CommandFlags.FireAndForget | CommandFlags.NoRedirect; @@ -458,7 +458,7 @@ internal async Task AutoConfigureAsync(PhysicalConnection? connection, ILogger? // But if GETs are disabled on this, do not fail the connection - we just don't get tiebreaker benefits if (Multiplexer.RawConfig.TryGetTieBreaker(out var tieBreakerKey) && Multiplexer.CommandMap.IsAvailable(RedisCommand.GET)) { - log?.LogInformation($"{Format.ToString(EndPoint)}: Requesting tie-break (Key=\"{tieBreakerKey}\")..."); + log?.LogInformationRequestingTieBreak(new LoggerExtensions.EndPointLogValue(EndPoint), tieBreakerKey.ToString()); msg = Message.Create(0, flags, RedisCommand.GET, tieBreakerKey); msg.SetInternalCall(); msg = LoggingMessage.Create(log, msg); @@ -929,7 +929,7 @@ internal ValueTask WriteDirectOrQueueFireAndForgetAsync(PhysicalConnection? c private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log) { - log?.LogInformation($"{Format.ToString(this)}: Server handshake"); + log?.LogInformationServerHandshake(new(this)); if (connection == null) { Multiplexer.Trace("No connection!?"); @@ -979,7 +979,7 @@ private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log) ResultProcessor? autoConfig = null; if (Multiplexer.RawConfig.TryResp3()) // note this includes an availability check on HELLO { - log?.LogInformation($"{Format.ToString(this)}: Authenticating via HELLO"); + log?.LogInformationAuthenticatingViaHello(new(this)); var hello = Message.CreateHello(3, user, password, clientName, CommandFlags.FireAndForget); hello.SetInternalCall(); await WriteDirectOrQueueFireAndForgetAsync(connection, hello, autoConfig ??= ResultProcessor.AutoConfigureProcessor.Create(log)).ForAwait(); @@ -997,14 +997,14 @@ private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log) // and: we're pipelined here, so... meh if (!string.IsNullOrWhiteSpace(user) && Multiplexer.CommandMap.IsAvailable(RedisCommand.AUTH)) { - log?.LogInformation($"{Format.ToString(this)}: Authenticating (user/password)"); + log?.LogInformationAuthenticatingUserPassword(new(this)); msg = Message.Create(-1, CommandFlags.FireAndForget, RedisCommand.AUTH, (RedisValue)user, (RedisValue)password); msg.SetInternalCall(); await WriteDirectOrQueueFireAndForgetAsync(connection, msg, ResultProcessor.DemandOK).ForAwait(); } else if (!string.IsNullOrWhiteSpace(password) && Multiplexer.CommandMap.IsAvailable(RedisCommand.AUTH)) { - log?.LogInformation($"{Format.ToString(this)}: Authenticating (password)"); + log?.LogInformationAuthenticatingPassword(new(this)); msg = Message.Create(-1, CommandFlags.FireAndForget, RedisCommand.AUTH, (RedisValue)password); msg.SetInternalCall(); await WriteDirectOrQueueFireAndForgetAsync(connection, msg, ResultProcessor.DemandOK).ForAwait(); @@ -1014,7 +1014,7 @@ private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log) { if (!string.IsNullOrWhiteSpace(clientName)) { - log?.LogInformation($"{Format.ToString(this)}: Setting client name: {clientName}"); + log?.LogInformationSettingClientName(new(this), clientName); msg = Message.Create(-1, CommandFlags.FireAndForget, RedisCommand.CLIENT, RedisLiterals.SETNAME, (RedisValue)clientName); msg.SetInternalCall(); await WriteDirectOrQueueFireAndForgetAsync(connection, msg, ResultProcessor.DemandOK).ForAwait(); @@ -1024,7 +1024,7 @@ private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log) { // note that this is a relatively new feature, but usually we won't know the // server version, so we will use this speculatively and hope for the best - log?.LogInformation($"{Format.ToString(this)}: Setting client lib/ver"); + log?.LogInformationSettingClientLibVer(new(this)); var libName = Multiplexer.GetFullLibraryName(); if (!string.IsNullOrWhiteSpace(libName)) @@ -1062,7 +1062,7 @@ private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log) var tracer = GetTracerMessage(true); tracer = LoggingMessage.Create(log, tracer); - log?.LogInformation($"{Format.ToString(this)}: Sending critical tracer (handshake): {tracer.CommandAndKey}"); + log?.LogInformationSendingCriticalTracer(new(this), tracer.CommandAndKey); await WriteDirectOrQueueFireAndForgetAsync(connection, tracer, ResultProcessor.EstablishConnection).ForAwait(); // Note: this **must** be the last thing on the subscription handshake, because after this @@ -1077,7 +1077,7 @@ private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log) await WriteDirectOrQueueFireAndForgetAsync(connection, msg, ResultProcessor.TrackSubscriptions).ForAwait(); } } - log?.LogInformation($"{Format.ToString(this)}: Flushing outbound buffer"); + log?.LogInformationFlushingOutboundBuffer(new(this)); await connection.FlushAsync().ForAwait(); } From 3df9326e3f459a9d9d81db5e5126c95b6ca5e0bb Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Wed, 23 Jul 2025 17:13:13 +0300 Subject: [PATCH 2/2] Improves type safety for tie-breaker key logging Changes parameter type from string to RedisKey in logging method to maintain type consistency throughout the tie-breaker request flow. Simplifies object instantiation using target-typed new expression. --- src/StackExchange.Redis/LoggerExtensions.cs | 2 +- src/StackExchange.Redis/ServerEndPoint.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/StackExchange.Redis/LoggerExtensions.cs b/src/StackExchange.Redis/LoggerExtensions.cs index 69fc1a7db..877de6257 100644 --- a/src/StackExchange.Redis/LoggerExtensions.cs +++ b/src/StackExchange.Redis/LoggerExtensions.cs @@ -439,7 +439,7 @@ internal static void LogWithThreadPoolStats(this ILogger? log, string message) Level = LogLevel.Information, EventId = 62, Message = "{EndPoint}: Requesting tie-break (Key=\"{TieBreakerKey}\")...")] - internal static partial void LogInformationRequestingTieBreak(this ILogger logger, EndPointLogValue endPoint, string tieBreakerKey); + internal static partial void LogInformationRequestingTieBreak(this ILogger logger, EndPointLogValue endPoint, RedisKey tieBreakerKey); [LoggerMessage( Level = LogLevel.Information, diff --git a/src/StackExchange.Redis/ServerEndPoint.cs b/src/StackExchange.Redis/ServerEndPoint.cs index 96b6bcc5a..e62dc9f43 100644 --- a/src/StackExchange.Redis/ServerEndPoint.cs +++ b/src/StackExchange.Redis/ServerEndPoint.cs @@ -458,7 +458,7 @@ internal async Task AutoConfigureAsync(PhysicalConnection? connection, ILogger? // But if GETs are disabled on this, do not fail the connection - we just don't get tiebreaker benefits if (Multiplexer.RawConfig.TryGetTieBreaker(out var tieBreakerKey) && Multiplexer.CommandMap.IsAvailable(RedisCommand.GET)) { - log?.LogInformationRequestingTieBreak(new LoggerExtensions.EndPointLogValue(EndPoint), tieBreakerKey.ToString()); + log?.LogInformationRequestingTieBreak(new(EndPoint), tieBreakerKey); msg = Message.Create(0, flags, RedisCommand.GET, tieBreakerKey); msg.SetInternalCall(); msg = LoggingMessage.Create(log, msg);