From 89922a399fcd474e4eaa09afdc999bbed40d09b7 Mon Sep 17 00:00:00 2001 From: James Newton-King Date: Sun, 15 Apr 2018 14:43:56 +1200 Subject: [PATCH] Capture server logs in tests --- .../HubConnectionTests.cs | 85 ++++++++++++++++--- .../ServerFixture.cs | 39 +++++++++ .../VerifiableLoggedTest.cs | 54 +++++++++++- .../EndToEndTests.cs | 4 +- .../WebSocketsTransportTests.cs | 4 +- 5 files changed, 167 insertions(+), 19 deletions(-) diff --git a/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs b/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs index 0121d2577f..b198d664ff 100644 --- a/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs @@ -30,11 +30,10 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests } [Collection(HubConnectionTestsCollection.Name)] - public class HubConnectionTests : VerifiableLoggedTest + public class HubConnectionTests : VerifiableServerLoggedTest { private readonly ServerFixture _serverFixture; - public HubConnectionTests(ServerFixture serverFixture, ITestOutputHelper output) - : base(output) + public HubConnectionTests(ServerFixture serverFixture, ITestOutputHelper output) : base(serverFixture, output) { if (serverFixture == null) { @@ -436,8 +435,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ExceptionFromStreamingSentToClient(string protocolName, HttpTransportType transportType, string path) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "FailedInvokingHubMethod"; + } + var protocol = HubProtocols[protocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ExceptionFromStreamingSentToClient)}_{protocol.Name}_{transportType}_{path.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ExceptionFromStreamingSentToClient)}_{protocol.Name}_{transportType}_{path.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(path, transportType, protocol, loggerFactory); try @@ -464,8 +469,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionIfHubMethodCannotBeResolved(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "UnknownHubMethod"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfHubMethodCannotBeResolved)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfHubMethodCannotBeResolved)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try @@ -491,8 +502,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionOnHubMethodArgumentCountMismatch(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "FailedInvokingHubMethod"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnHubMethodArgumentCountMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnHubMethodArgumentCountMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try @@ -518,8 +535,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionOnHubMethodArgumentTypeMismatch(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "FailedInvokingHubMethod"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnHubMethodArgumentTypeMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnHubMethodArgumentTypeMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try @@ -545,8 +568,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionIfStreamingHubMethodCannotBeResolved(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "UnknownHubMethod"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfStreamingHubMethodCannotBeResolved)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfStreamingHubMethodCannotBeResolved)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try @@ -573,8 +602,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionOnStreamingHubMethodArgumentCountMismatch(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "FailedInvokingHubMethod"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnStreamingHubMethodArgumentCountMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnStreamingHubMethodArgumentCountMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { loggerFactory.AddConsole(LogLevel.Trace); var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); @@ -602,8 +637,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionOnStreamingHubMethodArgumentTypeMismatch(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "FailedInvokingHubMethod"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnStreamingHubMethodArgumentTypeMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionOnStreamingHubMethodArgumentTypeMismatch)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try @@ -630,8 +671,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionIfNonStreamMethodInvokedWithStreamAsync(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "NonStreamingMethodCalledWithStream"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfNonStreamMethodInvokedWithStreamAsync)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfNonStreamMethodInvokedWithStreamAsync)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try @@ -657,8 +704,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionIfStreamMethodInvokedWithInvoke(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "StreamingMethodCalledWithInvoke"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfStreamMethodInvokedWithInvoke)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfStreamMethodInvokedWithInvoke)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try @@ -684,8 +737,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests [MemberData(nameof(HubProtocolsAndTransportsAndHubPaths))] public async Task ServerThrowsHubExceptionIfBuildingAsyncEnumeratorIsNotPossible(string hubProtocolName, HttpTransportType transportType, string hubPath) { + bool ExpectedErrors(WriteContext writeContext) + { + return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Tests.ServerLogScope" && + writeContext.EventId.Name == "InvalidReturnValueFromStreamingMethod"; + } + var hubProtocol = HubProtocols[hubProtocolName]; - using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfBuildingAsyncEnumeratorIsNotPossible)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}")) + using (StartVerifableLog(out var loggerFactory, $"{nameof(ServerThrowsHubExceptionIfBuildingAsyncEnumeratorIsNotPossible)}_{hubProtocol.Name}_{transportType}_{hubPath.TrimStart('/')}", expectedErrorsFilter: ExpectedErrors)) { var connection = CreateHubConnection(hubPath, transportType, hubProtocol, loggerFactory); try diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs index 462201fd75..31330b9181 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs @@ -29,6 +29,12 @@ namespace Microsoft.AspNetCore.SignalR.Tests private readonly LogSinkProvider _logSinkProvider; + internal event Action ServerLogged + { + add => _logSinkProvider.RecordLogged += value; + remove => _logSinkProvider.RecordLogged -= value; + } + public string WebSocketsUrl => Url.Replace("http", "ws"); public string Url { get; private set; } @@ -146,11 +152,42 @@ namespace Microsoft.AspNetCore.SignalR.Tests } } + //internal class ForwardingLoggerProvider : ILoggerProvider + //{ + // private readonly HashSet _loggerFactories; + + // public ForwardingLoggerProvider() + // { + // _loggerFactories = new HashSet(); + // } + + // public void AddFactory(ILoggerFactory loggerFactory) + // { + // _loggerFactories.Add(loggerFactory); + // } + + // public void RemoveFactory(ILoggerFactory loggerFactory) + // { + // _loggerFactories.Remove(loggerFactory); + // } + + // public void Dispose() + // { + // } + + // public ILogger CreateLogger(string categoryName) + // { + // return _loggerFactory.CreateLogger(categoryName); + // } + //} + // TestSink doesn't seem to be thread-safe :(. internal class LogSinkProvider : ILoggerProvider { private readonly ConcurrentQueue _logs = new ConcurrentQueue(); + public event Action RecordLogged; + public ILogger CreateLogger(string categoryName) { return new LogSinkLogger(categoryName, this); @@ -176,6 +213,8 @@ namespace Microsoft.AspNetCore.SignalR.Tests Formatter = (o, e) => formatter((TState)o, e), }); _logs.Enqueue(record); + + RecordLogged?.Invoke(record); } private class LogSinkLogger : ILogger diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs index 1968f3bcdd..9359c41876 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs @@ -11,20 +11,70 @@ using Xunit.Abstractions; namespace Microsoft.AspNetCore.SignalR.Tests { + public class VerifiableServerLoggedTest : VerifiableLoggedTest where TStartup : class + { + public ServerFixture ServerFixture { get; } + + public VerifiableServerLoggedTest(ServerFixture serverFixture, ITestOutputHelper output) : base(output) + { + ServerFixture = serverFixture; + } + + public override IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, string testName = null, Func expectedErrorsFilter = null) + { + var disposable = base.StartVerifableLog(out loggerFactory, minLogLevel, testName, expectedErrorsFilter); + return new ServerLogScope(ServerFixture, loggerFactory, disposable); + } + + public override IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, string testName = null, Func expectedErrorsFilter = null) + { + var disposable = base.StartVerifableLog(out loggerFactory, testName, expectedErrorsFilter); + return new ServerLogScope(ServerFixture, loggerFactory, disposable); + } + } + + public class ServerLogScope : IDisposable where TStartup : class + { + private readonly ServerFixture _serverFixture; + private readonly IDisposable _wrappedDisposable; + private readonly ILogger _logger; + + public ServerLogScope(ServerFixture serverFixture, ILoggerFactory loggerFactory, IDisposable wrappedDisposable) + { + _serverFixture = serverFixture; + _wrappedDisposable = wrappedDisposable; + _logger = loggerFactory.CreateLogger(typeof(ServerLogScope)); + + _serverFixture.ServerLogged += ServerFixtureOnServerLogged; + } + + private void ServerFixtureOnServerLogged(LogRecord logRecord) + { + _logger.Log(logRecord.Write.LogLevel, logRecord.Write.EventId, logRecord.Write.State, logRecord.Write.Exception, logRecord.Write.Formatter); + } + + public void Dispose() + { + _serverFixture.ServerLogged -= ServerFixtureOnServerLogged; + + _wrappedDisposable?.Dispose(); + } + } + public class VerifiableLoggedTest : LoggedTest { public VerifiableLoggedTest(ITestOutputHelper output) : base(output) { } - public IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null, Func expectedErrorsFilter = null) + public virtual IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null, Func expectedErrorsFilter = null) { var disposable = StartLog(out loggerFactory, testName); return new VerifyNoErrorsScope(loggerFactory, disposable, expectedErrorsFilter); } - public IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, [CallerMemberName] string testName = null, Func expectedErrorsFilter = null) + public virtual IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, [CallerMemberName] string testName = null, Func expectedErrorsFilter = null) { var disposable = StartLog(out loggerFactory, minLogLevel, testName); diff --git a/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs b/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs index 8c5096b319..168e2e77d8 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs @@ -34,11 +34,11 @@ namespace Microsoft.AspNetCore.SignalR.Tests } [Collection(EndToEndTestsCollection.Name)] - public class EndToEndTests : VerifiableLoggedTest + public class EndToEndTests : VerifiableServerLoggedTest { private readonly ServerFixture _serverFixture; - public EndToEndTests(ServerFixture serverFixture, ITestOutputHelper output) : base(output) + public EndToEndTests(ServerFixture serverFixture, ITestOutputHelper output) : base(serverFixture, output) { if (serverFixture == null) { diff --git a/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs b/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs index 18c3d64437..4f7aaae831 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs @@ -22,11 +22,11 @@ using Xunit.Abstractions; namespace Microsoft.AspNetCore.SignalR.Tests { [Collection(EndToEndTestsCollection.Name)] - public class WebSocketsTransportTests : VerifiableLoggedTest + public class WebSocketsTransportTests : VerifiableServerLoggedTest { private readonly ServerFixture _serverFixture; - public WebSocketsTransportTests(ServerFixture serverFixture, ITestOutputHelper output) : base(output) + public WebSocketsTransportTests(ServerFixture serverFixture, ITestOutputHelper output) : base(serverFixture, output) { if (serverFixture == null) {