Capture server logs in tests (#2029)

dotnet · Apr 18, 2018 · 391c281 · 391c281
2 parents 31debcb + 61cce23
commit 391c281
Show file tree

Hide file tree

Showing 12 changed files with 263 additions and 92 deletions.
diff --git a/build/repo.props b/build/repo.props
@@ -1,4 +1,4 @@
-<Project>
+<Project>
   <Import Project="dependencies.props" />
 
   <PropertyGroup>

diff --git a/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LoggingHttpMessageHandler.cs b/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LoggingHttpMessageHandler.cs
@@ -43,16 +43,16 @@ private static class Log
             private static readonly Action<ILogger, HttpMethod, Uri, Exception> _sendingHttpRequest =
                 LoggerMessage.Define<HttpMethod, Uri>(LogLevel.Trace, new EventId(1, "SendingHttpRequest"), "Sending HTTP request {RequestMethod} '{RequestUrl}'.");
 
-            private static readonly Action<ILogger, HttpStatusCode, HttpMethod, Uri, Exception> _unsuccessfulHttpResponse =
-                LoggerMessage.Define<HttpStatusCode, HttpMethod, Uri>(LogLevel.Warning, new EventId(2, "UnsuccessfulHttpResponse"), "Unsuccessful HTTP response status code of {StatusCode} return from {RequestMethod} '{RequestUrl}'.");
+            private static readonly Action<ILogger, int, HttpMethod, Uri, Exception> _unsuccessfulHttpResponse =
+                LoggerMessage.Define<int, HttpMethod, Uri>(LogLevel.Warning, new EventId(2, "UnsuccessfulHttpResponse"), "Unsuccessful HTTP response {StatusCode} return from {RequestMethod} '{RequestUrl}'.");
 
             public static void SendingHttpRequest(ILogger logger, HttpMethod requestMethod, Uri requestUrl)
             {
                 _sendingHttpRequest(logger, requestMethod, requestUrl, null);
             }
             public static void UnsuccessfulHttpResponse(ILogger logger, HttpStatusCode statusCode, HttpMethod requestMethod, Uri requestUrl)
             {
-                _unsuccessfulHttpResponse(logger, statusCode, requestMethod, requestUrl, null);
+                _unsuccessfulHttpResponse(logger, (int)statusCode, requestMethod, requestUrl, null);
             }
         }
     }

diff --git a/src/Microsoft.AspNetCore.Http.Connections/Internal/Transports/WebSocketsTransport.Log.cs b/src/Microsoft.AspNetCore.Http.Connections/Internal/Transports/WebSocketsTransport.Log.cs
@@ -50,6 +50,9 @@ private static class Log
             private static readonly Action<ILogger, Exception> _sendFailed =
                 LoggerMessage.Define(LogLevel.Error, new EventId(13, "SendFailed"), "Socket failed to send.");
 
+            private static readonly Action<ILogger, Exception> _closedPrematurely =
+                LoggerMessage.Define(LogLevel.Debug, new EventId(14, "ClosedPrematurely"), "Socket connection closed prematurely.");
+
             public static void SocketOpened(ILogger logger, string subProtocol)
             {
                 _socketOpened(logger, subProtocol, null);
@@ -115,6 +118,10 @@ public static void SendFailed(ILogger logger, Exception ex)
                 _sendFailed(logger, ex);
             }
 
+            public static void ClosedPrematurely(ILogger logger, Exception ex)
+            {
+                _closedPrematurely(logger, ex);
+            }
         }
     }
 }
diff --git a/src/Microsoft.AspNetCore.Http.Connections/Internal/Transports/WebSocketsTransport.cs b/src/Microsoft.AspNetCore.Http.Connections/Internal/Transports/WebSocketsTransport.cs
@@ -182,6 +182,11 @@ private async Task StartReceiving(WebSocket socket)
                     }
                 }
             }
+            catch (WebSocketException ex) when (ex.WebSocketErrorCode == WebSocketError.ConnectionClosedPrematurely)
+            {
+                // Client has closed the WebSocket connection without completing the close handshake
+                Log.ClosedPrematurely(_logger, ex);
+            }
             catch (OperationCanceledException)
             {
                 // Ignore aborts, don't treat them like transport errors

diff --git a/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs b/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs
diff --git a/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs b/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs
@@ -17,13 +17,14 @@
 
 namespace Microsoft.AspNetCore.SignalR.Redis.Tests
 {
-    [CollectionDefinition(Name)]
-    public class EndToEndTestsCollection : ICollectionFixture<RedisServerFixture<Startup>>
+    // Disable running server tests in parallel so server logs can accurately be captured per test
+    [CollectionDefinition(Name, DisableParallelization = true)]
+    public class RedisEndToEndTestsCollection : ICollectionFixture<RedisServerFixture<Startup>>
     {
-        public const string Name = "RedisEndToEndTests";
+        public const string Name = nameof(RedisEndToEndTestsCollection);
     }
 
-    [Collection(EndToEndTestsCollection.Name)]
+    [Collection(RedisEndToEndTestsCollection.Name)]
     public class RedisEndToEndTests : VerifiableLoggedTest
     {
         private readonly RedisServerFixture<Startup> _serverFixture;

diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs
@@ -18,7 +18,18 @@
 
 namespace Microsoft.AspNetCore.SignalR.Tests
 {
-    public class ServerFixture<TStartup> : IDisposable
+    public abstract class ServerFixture : IDisposable
+    {
+        internal abstract event Action<LogRecord> ServerLogged;
+
+        public abstract string WebSocketsUrl { get; }
+
+        public abstract string Url { get; }
+
+        public abstract void Dispose();
+    }
+
+    public class ServerFixture<TStartup> : ServerFixture
         where TStartup : class
     {
         private readonly ILoggerFactory _loggerFactory;
@@ -28,10 +39,17 @@ public class ServerFixture<TStartup> : IDisposable
         private readonly IDisposable _logToken;
 
         private readonly LogSinkProvider _logSinkProvider;
+        private string _url;
 
-        public string WebSocketsUrl => Url.Replace("http", "ws");
+        internal override event Action<LogRecord> ServerLogged
+        {
+            add => _logSinkProvider.RecordLogged += value;
+            remove => _logSinkProvider.RecordLogged -= value;
+        }
+
+        public override string WebSocketsUrl => Url.Replace("http", "ws");
 
-        public string Url { get; private set; }
+        public override string Url => _url;
 
         public ServerFixture() : this(loggerFactory: null)
         {
@@ -64,7 +82,7 @@ private void StartServer()
 
             _host = new WebHostBuilder()
                 .ConfigureLogging(builder => builder
-                    .SetMinimumLevel(LogLevel.Debug)
+                    .SetMinimumLevel(LogLevel.Trace)
                     .AddProvider(_logSinkProvider)
                     .AddProvider(new ForwardingLoggerProvider(_loggerFactory)))
                 .UseStartup(typeof(TStartup))
@@ -92,7 +110,7 @@ private void StartServer()
             _logger.LogInformation("Test Server started");
 
             // Get the URL from the server
-            Url = _host.ServerFeatures.Get<IServerAddressesFeature>().Addresses.Single();
+            _url = _host.ServerFeatures.Get<IServerAddressesFeature>().Addresses.Single();
 
             _lifetime.ApplicationStopped.Register(() =>
             {
@@ -119,7 +137,7 @@ private string RenderLogs(IList<LogRecord> logs)
             return builder.ToString();
         }
 
-        public void Dispose()
+        public override void Dispose()
         {
             _logger.LogInformation("Shutting down test server");
             _host.Dispose();
@@ -151,6 +169,8 @@ 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 +196,8 @@ public void Log<TState>(string categoryName, LogLevel logLevel, EventId eventId,
                     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/ServerLogScope.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerLogScope.cs
@@ -0,0 +1,68 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using System.Collections.Concurrent;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.AspNetCore.SignalR.Tests
+{
+    public class ServerLogScope : IDisposable
+    {
+        private readonly ServerFixture _serverFixture;
+        private readonly ILoggerFactory _loggerFactory;
+        private readonly IDisposable _wrappedDisposable;
+        private readonly ConcurrentDictionary<string, ILogger> _serverLoggers;
+        private readonly ILogger _scopeLogger;
+        private readonly object _lock;
+
+        public ServerLogScope(ServerFixture serverFixture, ILoggerFactory loggerFactory, IDisposable wrappedDisposable)
+        {
+            _loggerFactory = loggerFactory;
+            _serverFixture = serverFixture;
+            _wrappedDisposable = wrappedDisposable;
+
+            _lock = new object();
+
+            _serverLoggers = new ConcurrentDictionary<string, ILogger>(StringComparer.Ordinal);
+            _scopeLogger = _loggerFactory.CreateLogger(nameof(ServerLogScope));
+
+            // Attach last after everything else is initialized because a logged error can happen at any time
+            _serverFixture.ServerLogged += ServerFixtureOnServerLogged;
+
+            _scopeLogger.LogInformation("Server log scope started.");
+        }
+
+        private void ServerFixtureOnServerLogged(LogRecord logRecord)
+        {
+            var write = logRecord.Write;
+
+            if (write == null)
+            {
+                _scopeLogger.LogWarning("Server log has no data.");
+                return;
+            }
+
+            ILogger logger;
+
+            // There maybe thready safety issues in logging when creating multiple loggers at the same time
+            // https://github.com/aspnet/Logging/issues/810
+            lock (_lock)
+            {
+                // Create (or get) a logger with the same name as the server logger
+                logger = _serverLoggers.GetOrAdd(write.LoggerName, loggerName => _loggerFactory.CreateLogger(loggerName));
+            }
+
+            logger.Log(write.LogLevel, write.EventId, write.State, write.Exception, write.Formatter);
+        }
+
+        public void Dispose()
+        {
+            _serverFixture.ServerLogged -= ServerFixtureOnServerLogged;
+
+            _scopeLogger.LogInformation("Server log scope stopped.");
+
+            _wrappedDisposable?.Dispose();
+        }
+    }
+}
diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs
@@ -17,14 +17,14 @@ 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);
 

diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableServerLoggedTest.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableServerLoggedTest.cs
@@ -0,0 +1,33 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using System.Runtime.CompilerServices;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
+using Xunit.Abstractions;
+
+namespace Microsoft.AspNetCore.SignalR.Tests
+{
+    public class VerifiableServerLoggedTest : VerifiableLoggedTest
+    {
+        public ServerFixture ServerFixture { get; }
+
+        public VerifiableServerLoggedTest(ServerFixture serverFixture, ITestOutputHelper output) : base(output)
+        {
+            ServerFixture = serverFixture;
+        }
+
+        public override IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, [CallerMemberName] string testName = null, Func<WriteContext, bool> expectedErrorsFilter = null)
+        {
+            var disposable = base.StartVerifableLog(out loggerFactory, minLogLevel, testName, expectedErrorsFilter);
+            return new ServerLogScope(ServerFixture, loggerFactory, disposable);
+        }
+
+        public override IDisposable StartVerifableLog(out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null, Func<WriteContext, bool> expectedErrorsFilter = null)
+        {
+            var disposable = base.StartVerifableLog(out loggerFactory, testName, expectedErrorsFilter);
+            return new ServerLogScope(ServerFixture, loggerFactory, disposable);
+        }
+    }
+}