From d1d16c3681b743ed111e1d9668f052d3a8d4661c Mon Sep 17 00:00:00 2001 From: Brennan Date: Mon, 11 Apr 2022 15:50:58 -0700 Subject: [PATCH 1/2] Add redis startup error handling --- .../src/Internal/RedisLog.cs | 3 ++ .../src/RedisHubLifetimeManager.cs | 21 +++++++-- .../test/RedisHubLifetimeManagerTests.cs | 45 +++++++++++++++++++ 3 files changed, 66 insertions(+), 3 deletions(-) diff --git a/src/SignalR/server/StackExchangeRedis/src/Internal/RedisLog.cs b/src/SignalR/server/StackExchangeRedis/src/Internal/RedisLog.cs index ba7217748af2..5df4804c52f4 100644 --- a/src/SignalR/server/StackExchangeRedis/src/Internal/RedisLog.cs +++ b/src/SignalR/server/StackExchangeRedis/src/Internal/RedisLog.cs @@ -58,6 +58,9 @@ public static void ConnectingToEndpoints(ILogger logger, EndPointCollection endp [LoggerMessage(13, LogLevel.Error, "Error forwarding client result with ID '{InvocationID}' to server.", EventName = "ErrorForwardingResult")] public static partial void ErrorForwardingResult(ILogger logger, string invocationId, Exception ex); + [LoggerMessage(14, LogLevel.Error, "Error connecting to Redis.", EventName = "ErrorConnecting")] + public static partial void ErrorConnecting(ILogger logger, Exception ex); + // This isn't DefineMessage-based because it's just the simple TextWriter logging from ConnectionMultiplexer public static void ConnectionMultiplexerMessage(ILogger logger, string? message) { diff --git a/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs b/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs index 6af795083e08..7d6facf92f38 100644 --- a/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs +++ b/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs @@ -90,6 +90,7 @@ public RedisHubLifetimeManager(ILogger> logger, public override async Task OnConnectedAsync(HubConnectionContext connection) { await EnsureRedisServerConnection(); + var feature = new RedisFeature(); connection.Features.Set(feature); @@ -112,11 +113,17 @@ public override Task OnDisconnectedAsync(HubConnectionContext connection) { _connections.Remove(connection); - var tasks = new List(); + // If the bus is null then the Redis connection failed to be established and none of the other connection setup ran + if (_bus is null) + { + return Task.CompletedTask; + } var connectionChannel = _channels.Connection(connection.ConnectionId); + var tasks = new List(); + RedisLog.Unsubscribe(_logger, connectionChannel); - tasks.Add(_bus!.UnsubscribeAsync(connectionChannel)); + tasks.Add(_bus.UnsubscribeAsync(connectionChannel)); var feature = connection.Features.GetRequiredFeature(); var groupNames = feature.Groups; @@ -704,7 +711,15 @@ private async Task EnsureRedisServerConnection() if (_redisServerConnection == null) { var writer = new LoggerTextWriter(_logger); - _redisServerConnection = await _options.ConnectAsync(writer); + try + { + _redisServerConnection = await _options.ConnectAsync(writer); + } + catch (Exception ex) + { + RedisLog.ErrorConnecting(_logger, ex); + throw; + } _bus = _redisServerConnection.GetSubscriber(); _redisServerConnection.ConnectionRestored += (_, e) => diff --git a/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs b/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs index 1d413bb54b8c..484c75a85763 100644 --- a/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs +++ b/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs @@ -7,8 +7,11 @@ using Microsoft.AspNetCore.SignalR.Specification.Tests; using Microsoft.AspNetCore.SignalR.Tests; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; using Microsoft.Extensions.Options; +using Moq; using Newtonsoft.Json.Linq; using Newtonsoft.Json.Serialization; using Xunit; @@ -83,6 +86,48 @@ public async Task CamelCasedJsonIsPreservedAcrossRedisBoundary() } } + [Fact] + public async Task ErrorFromConnectionFactoryLogsAndAllowsDisconnect() + { + var server = new TestRedisServer(); + + var testSink = new TestSink(); + var logger = new TestLogger("", testSink, true); + var mockLoggerFactory = new Mock(); + mockLoggerFactory + .Setup(m => m.CreateLogger(It.IsAny())) + .Returns((string categoryName) => (ILogger)logger); + var loggerT = mockLoggerFactory.Object.CreateLogger>(); + + var manager = new RedisHubLifetimeManager( + loggerT, + Options.Create(new RedisOptions() + { + ConnectionFactory = _ => throw new Exception("throw from connect") + }), + new DefaultHubProtocolResolver(new IHubProtocol[] + { + }, NullLogger.Instance)); + + using (var client = new TestClient()) + { + var connection = HubConnectionContextUtils.Create(client.Connection); + + var ex = await Assert.ThrowsAsync(() => manager.OnConnectedAsync(connection)).DefaultTimeout(); + Assert.Equal("throw from connect", ex.Message); + + await manager.OnDisconnectedAsync(connection).DefaultTimeout(); + } + + var logs = testSink.Writes.ToArray(); + // Two of the same error logs, one for the pre-emptive attempt to connect to Redis in the ctor, and one during the OnConnectedAsync for the connection + Assert.Equal(2, logs.Length); + Assert.Equal("Error connecting to Redis.", logs[0].Message); + Assert.Equal("throw from connect", logs[0].Exception.Message); + Assert.Equal("Error connecting to Redis.", logs[1].Message); + Assert.Equal("throw from connect", logs[1].Exception.Message); + } + public override TestRedisServer CreateBackplane() { return new TestRedisServer(); From 7e32bedb6e967d85e16b9144fb636cd4ce7d8c47 Mon Sep 17 00:00:00 2001 From: Brennan Date: Wed, 1 Jun 2022 10:21:21 -0700 Subject: [PATCH 2/2] fb --- .../StackExchangeRedis/src/RedisHubLifetimeManager.cs | 9 ++++++++- .../test/RedisHubLifetimeManagerTests.cs | 5 +---- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs b/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs index 7d6facf92f38..ef8ef660e67e 100644 --- a/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs +++ b/src/SignalR/server/StackExchangeRedis/src/RedisHubLifetimeManager.cs @@ -35,6 +35,7 @@ public class RedisHubLifetimeManager : HubLifetimeManager, IDisposab private readonly SemaphoreSlim _connectionLock = new SemaphoreSlim(1); private readonly IHubProtocolResolver _hubProtocolResolver; private readonly ClientResultsManager _clientResultsManager = new(); + private bool _redisConnectErrorLogged; private readonly AckHandler _ackHandler; private int _internalAckId; @@ -717,7 +718,13 @@ private async Task EnsureRedisServerConnection() } catch (Exception ex) { - RedisLog.ErrorConnecting(_logger, ex); + // If the connection hasn't been established yet we shouldn't keep logging the same error over and over + // for every new client connection. + if (!_redisConnectErrorLogged) + { + RedisLog.ErrorConnecting(_logger, ex); + _redisConnectErrorLogged = true; + } throw; } _bus = _redisServerConnection.GetSubscriber(); diff --git a/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs b/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs index 484c75a85763..57827e499c67 100644 --- a/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs +++ b/src/SignalR/server/StackExchangeRedis/test/RedisHubLifetimeManagerTests.cs @@ -120,12 +120,9 @@ public async Task ErrorFromConnectionFactoryLogsAndAllowsDisconnect() } var logs = testSink.Writes.ToArray(); - // Two of the same error logs, one for the pre-emptive attempt to connect to Redis in the ctor, and one during the OnConnectedAsync for the connection - Assert.Equal(2, logs.Length); + Assert.Single(logs); Assert.Equal("Error connecting to Redis.", logs[0].Message); Assert.Equal("throw from connect", logs[0].Exception.Message); - Assert.Equal("Error connecting to Redis.", logs[1].Message); - Assert.Equal("throw from connect", logs[1].Exception.Message); } public override TestRedisServer CreateBackplane()