Capture server logs in tests

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<Startup>
     {
         private readonly ServerFixture<Startup> _serverFixture;
-        public HubConnectionTests(ServerFixture<Startup> serverFixture, ITestOutputHelper output)
+        public HubConnectionTests(ServerFixture<Startup> serverFixture, ITestOutputHelper output) : base(serverFixture, output)
-            : base(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

test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs

@@ -29,6 +29,12 @@ namespace Microsoft.AspNetCore.SignalR.Tests
 
         private readonly LogSinkProvider _logSinkProvider;
 
+        internal event Action<LogRecord> 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<ILoggerFactory> _loggerFactories;
+
+    //    public ForwardingLoggerProvider()
+    //    {
+    //        _loggerFactories = new HashSet<ILoggerFactory>();
+    //    }
+
+    //    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<LogRecord> _logs = new ConcurrentQueue<LogRecord>();
 
+        public event Action<LogRecord> 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

test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs

@@ -11,20 +11,70 @@ using Xunit.Abstractions;
 
 namespace Microsoft.AspNetCore.SignalR.Tests
 {
+    public class VerifiableServerLoggedTest<TStartup> : VerifiableLoggedTest where TStartup : class 
+    {
+        public ServerFixture<TStartup> ServerFixture { get; }
+
+        public VerifiableServerLoggedTest(ServerFixture<TStartup> serverFixture, ITestOutputHelper output) : base(output)
+        {
+            ServerFixture = serverFixture;
+        }
+
+        public override IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, string testName = null, Func<WriteContext, bool> expectedErrorsFilter = null)
+        {
+            var disposable = base.StartVerifableLog(out loggerFactory, minLogLevel, testName, expectedErrorsFilter);
+            return new ServerLogScope<TStartup>(ServerFixture, loggerFactory, disposable);
+        }
+
+        public override IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, string testName = null, Func<WriteContext, bool> expectedErrorsFilter = null)
+        {
+            var disposable = base.StartVerifableLog(out loggerFactory, testName, expectedErrorsFilter);
+            return new ServerLogScope<TStartup>(ServerFixture, loggerFactory, disposable);
+        }
+    }
+
+    public class ServerLogScope<TStartup> : IDisposable where TStartup : class
+    {
+        private readonly ServerFixture<TStartup> _serverFixture;
+        private readonly IDisposable _wrappedDisposable;
+        private readonly ILogger _logger;
+
+        public ServerLogScope(ServerFixture<TStartup> serverFixture, ILoggerFactory loggerFactory, IDisposable wrappedDisposable)
+        {
+            _serverFixture = serverFixture;
+            _wrappedDisposable = wrappedDisposable;
+            _logger = loggerFactory.CreateLogger(typeof(ServerLogScope<TStartup>));
+
+            _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<WriteContext, bool> expectedErrorsFilter = null)
+        public virtual IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null, Func<WriteContext, bool> 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<WriteContext, bool> expectedErrorsFilter = null)
+        public virtual IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, [CallerMemberName] string testName = null, Func<WriteContext, bool> expectedErrorsFilter = null)
         {
             var disposable = StartLog(out loggerFactory, minLogLevel, testName);
 

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<Startup>
     {
         private readonly ServerFixture<Startup> _serverFixture;
 
-        public EndToEndTests(ServerFixture<Startup> serverFixture, ITestOutputHelper output) : base(output)
+        public EndToEndTests(ServerFixture<Startup> serverFixture, ITestOutputHelper output) : base(serverFixture, output)
         {
             if (serverFixture == null)
             {

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<Startup>
     {
         private readonly ServerFixture<Startup> _serverFixture;
 
-        public WebSocketsTransportTests(ServerFixture<Startup> serverFixture, ITestOutputHelper output) : base(output)
+        public WebSocketsTransportTests(ServerFixture<Startup> serverFixture, ITestOutputHelper output) : base(serverFixture, output)
         {
             if (serverFixture == null)
             {