From dee14b7eb5cc68000fefdbe1f1e5ab41e8e5dc65 Mon Sep 17 00:00:00 2001 From: Andrew Stanton-Nurse Date: Thu, 2 Apr 2020 23:41:34 -0700 Subject: [PATCH] fix #13651 by logging serialization failures as error (#20116) --- .../FunctionalTests/HubConnectionTests.cs | 96 +++++++++++++++++++ .../Client/test/FunctionalTests/Hubs.cs | 27 ++++++ .../Tests.Utils/InProcessTestServer.cs | 2 + .../testassets/Tests.Utils/LogRecord.cs | 2 +- .../server/Core/src/HubConnectionContext.cs | 2 +- .../SignalR/test/HubConnectionHandlerTests.cs | 2 +- 6 files changed, 128 insertions(+), 3 deletions(-) diff --git a/src/SignalR/clients/csharp/Client/test/FunctionalTests/HubConnectionTests.cs b/src/SignalR/clients/csharp/Client/test/FunctionalTests/HubConnectionTests.cs index 2220685e82..afe4254ded 100644 --- a/src/SignalR/clients/csharp/Client/test/FunctionalTests/HubConnectionTests.cs +++ b/src/SignalR/clients/csharp/Client/test/FunctionalTests/HubConnectionTests.cs @@ -1335,6 +1335,102 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests } } + [Theory] + [QuarantinedTest] + [MemberData(nameof(HubProtocolsList))] + public async Task ServerLogsErrorIfClientInvokeCannotBeSerialized(string protocolName) + { + // Just to help sanity check that the right exception is thrown + var exceptionSubstring = protocolName switch + { + "json" => "A possible object cycle was detected.", + "newtonsoft-json" => "A possible object cycle was detected.", + "messagepack" => "Failed to serialize Microsoft.AspNetCore.SignalR.Client.FunctionalTests.TestHub+Unserializable value.", + var x => throw new Exception($"The test does not have an exception string for the protocol '{x}'!"), + }; + + var protocol = HubProtocols[protocolName]; + using (var server = await StartServer(write => write.EventId.Name == "FailedWritingMessage")) + { + var connection = CreateHubConnection(server.Url, "/default", HttpTransportType.WebSockets, protocol, LoggerFactory); + var closedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + connection.Closed += (ex) => { closedTcs.TrySetResult(ex); return Task.CompletedTask; }; + try + { + await connection.StartAsync().OrTimeout(); + + var result = connection.InvokeAsync(nameof(TestHub.CallWithUnserializableObject)); + + // The connection should close. + Assert.Null(await closedTcs.Task.OrTimeout()); + + await Assert.ThrowsAsync(() => result).OrTimeout(); + } + catch (Exception ex) + { + LoggerFactory.CreateLogger().LogError(ex, "{ExceptionType} from test", ex.GetType().FullName); + throw; + } + finally + { + await connection.DisposeAsync().OrTimeout(); + } + + var errorLog = server.GetLogs().SingleOrDefault(r => r.Write.EventId.Name == "FailedWritingMessage"); + Assert.NotNull(errorLog); + Assert.Contains(exceptionSubstring, errorLog.Write.Exception.Message); + Assert.Equal(LogLevel.Error, errorLog.Write.LogLevel); + } + } + + [Theory] + [QuarantinedTest] + [MemberData(nameof(HubProtocolsList))] + public async Task ServerLogsErrorIfReturnValueCannotBeSerialized(string protocolName) + { + // Just to help sanity check that the right exception is thrown + var exceptionSubstring = protocolName switch + { + "json" => "A possible object cycle was detected.", + "newtonsoft-json" => "A possible object cycle was detected.", + "messagepack" => "Failed to serialize Microsoft.AspNetCore.SignalR.Client.FunctionalTests.TestHub+Unserializable value.", + var x => throw new Exception($"The test does not have an exception string for the protocol '{x}'!"), + }; + + var protocol = HubProtocols[protocolName]; + using (var server = await StartServer(write => write.EventId.Name == "FailedWritingMessage")) + { + var connection = CreateHubConnection(server.Url, "/default", HttpTransportType.LongPolling, protocol, LoggerFactory); + var closedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + connection.Closed += (ex) => { closedTcs.TrySetResult(ex); return Task.CompletedTask; }; + try + { + await connection.StartAsync().OrTimeout(); + + var result = connection.InvokeAsync(nameof(TestHub.GetUnserializableObject)).OrTimeout(); + + // The connection should close. + Assert.Null(await closedTcs.Task.OrTimeout()); + + await Assert.ThrowsAsync(() => result).OrTimeout(); + } + catch (Exception ex) + { + LoggerFactory.CreateLogger().LogError(ex, "{ExceptionType} from test", ex.GetType().FullName); + throw; + } + finally + { + await connection.DisposeAsync().OrTimeout(); + } + + var errorLog = server.GetLogs().SingleOrDefault(r => r.Write.EventId.Name == "FailedWritingMessage"); + Assert.NotNull(errorLog); + Assert.Contains(exceptionSubstring, errorLog.Write.Exception.Message); + Assert.Equal(LogLevel.Error, errorLog.Write.LogLevel); + } + } + [Fact] public async Task RandomGenericIsNotTreatedAsStream() { diff --git a/src/SignalR/clients/csharp/Client/test/FunctionalTests/Hubs.cs b/src/SignalR/clients/csharp/Client/test/FunctionalTests/Hubs.cs index 01ce4198c4..90328a6b57 100644 --- a/src/SignalR/clients/csharp/Client/test/FunctionalTests/Hubs.cs +++ b/src/SignalR/clients/csharp/Client/test/FunctionalTests/Hubs.cs @@ -95,6 +95,33 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { return Context.Features.Get().TransportType.ToString(); } + + public async Task CallWithUnserializableObject() + { + await Clients.All.SendAsync("Foo", Unserializable.Create()); + } + + public Unserializable GetUnserializableObject() + { + return Unserializable.Create(); + } + + public class Unserializable + { + public Unserializable Child { get; private set; } + + private Unserializable() + { + } + + internal static Unserializable Create() + { + // Loops throw off every serializer ;). + var o = new Unserializable(); + o.Child = o; + return o; + } + } } public class DynamicTestHub : DynamicHub diff --git a/src/SignalR/common/testassets/Tests.Utils/InProcessTestServer.cs b/src/SignalR/common/testassets/Tests.Utils/InProcessTestServer.cs index a02e4bb1de..631220c7de 100644 --- a/src/SignalR/common/testassets/Tests.Utils/InProcessTestServer.cs +++ b/src/SignalR/common/testassets/Tests.Utils/InProcessTestServer.cs @@ -84,6 +84,8 @@ namespace Microsoft.AspNetCore.SignalR.Tests _logger = _loggerFactory.CreateLogger>(); } + public IList GetLogs() => _logSinkProvider.GetLogs(); + private async Task StartServerInner() { // We're using 127.0.0.1 instead of localhost to ensure that we use IPV4 across different OSes diff --git a/src/SignalR/common/testassets/Tests.Utils/LogRecord.cs b/src/SignalR/common/testassets/Tests.Utils/LogRecord.cs index 9193044270..7c9d9f071c 100644 --- a/src/SignalR/common/testassets/Tests.Utils/LogRecord.cs +++ b/src/SignalR/common/testassets/Tests.Utils/LogRecord.cs @@ -7,7 +7,7 @@ using Microsoft.Extensions.Logging.Testing; namespace Microsoft.AspNetCore.SignalR.Tests { // WriteContext, but with a timestamp... - internal class LogRecord + public class LogRecord { public DateTime Timestamp { get; } public WriteContext Write { get; } diff --git a/src/SignalR/server/Core/src/HubConnectionContext.cs b/src/SignalR/server/Core/src/HubConnectionContext.cs index 91516701e4..fcd704c428 100644 --- a/src/SignalR/server/Core/src/HubConnectionContext.cs +++ b/src/SignalR/server/Core/src/HubConnectionContext.cs @@ -689,7 +689,7 @@ namespace Microsoft.AspNetCore.SignalR LoggerMessage.Define(LogLevel.Debug, new EventId(5, "HandshakeFailed"), "Failed connection handshake."); private static readonly Action _failedWritingMessage = - LoggerMessage.Define(LogLevel.Debug, new EventId(6, "FailedWritingMessage"), "Failed writing message. Aborting connection."); + LoggerMessage.Define(LogLevel.Error, new EventId(6, "FailedWritingMessage"), "Failed writing message. Aborting connection."); private static readonly Action _protocolVersionFailed = LoggerMessage.Define(LogLevel.Debug, new EventId(7, "ProtocolVersionFailed"), "Server does not support version {Version} of the {Protocol} protocol."); diff --git a/src/SignalR/server/SignalR/test/HubConnectionHandlerTests.cs b/src/SignalR/server/SignalR/test/HubConnectionHandlerTests.cs index d65de0ba1f..eb6d11a9dc 100644 --- a/src/SignalR/server/SignalR/test/HubConnectionHandlerTests.cs +++ b/src/SignalR/server/SignalR/test/HubConnectionHandlerTests.cs @@ -3299,7 +3299,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests [Fact] public async Task ConnectionAbortedIfSendFailsWithProtocolError() { - using (StartVerifiableLog()) + using (StartVerifiableLog(write => write.EventId.Name == "FailedWritingMessage")) { var serviceProvider = HubConnectionHandlerTestUtils.CreateServiceProvider(services => {