Skip to content

chore: Replaces string interpolation with structured logging - ServerEndPoint #2924

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Jul 23, 2025
Merged

chore: Replaces string interpolation with structured logging - ServerEndPoint #2924

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
fb357ba
chore: Replaces string interpolation with structured logging
Meir017 Jul 23, 2025
3df9326
Improves type safety for tie-breaker key logging
Meir017 Jul 23, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
85 changes: 85 additions & 0 deletions src/StackExchange.Redis/LoggerExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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, RedisKey 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);
}
28 changes: 14 additions & 14 deletions src/StackExchange.Redis/ServerEndPoint.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -116,7 +116,7 @@ public Task<string> OnConnectedAsync(ILogger? log = null, bool sendTracerIfConne
{
async Task<string> 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();
Expand All @@ -125,15 +125,15 @@ async Task<string> 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<string>(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);
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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(EndPoint), tieBreakerKey);
msg = Message.Create(0, flags, RedisCommand.GET, tieBreakerKey);
msg.SetInternalCall();
msg = LoggingMessage.Create(log, msg);
Expand Down Expand Up @@ -929,7 +929,7 @@ internal ValueTask WriteDirectOrQueueFireAndForgetAsync<T>(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!?");
Expand Down Expand Up @@ -979,7 +979,7 @@ private async Task HandshakeAsync(PhysicalConnection connection, ILogger? log)
ResultProcessor<bool>? 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();
Expand All @@ -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();
Expand All @@ -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();
Expand All @@ -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))
Expand Down Expand Up @@ -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
Expand All @@ -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();
}

Expand Down
Loading