diff --git a/src/StackExchange.Redis/LoggerExtensions.cs b/src/StackExchange.Redis/LoggerExtensions.cs index 3cb2ec6fb..759c3949b 100644 --- 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 index f5d75c188..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?.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 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;