diff --git a/build/repo.props b/build/repo.props index b214eab03b..38e1626110 100644 --- a/build/repo.props +++ b/build/repo.props @@ -1,4 +1,4 @@ - + diff --git a/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LoggingHttpMessageHandler.cs b/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LoggingHttpMessageHandler.cs index 7d8df64783..d8a90205fa 100644 --- a/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LoggingHttpMessageHandler.cs +++ b/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LoggingHttpMessageHandler.cs @@ -43,8 +43,8 @@ namespace Microsoft.AspNetCore.Http.Connections.Client.Internal private static readonly Action _sendingHttpRequest = LoggerMessage.Define(LogLevel.Trace, new EventId(1, "SendingHttpRequest"), "Sending HTTP request {RequestMethod} '{RequestUrl}'."); - private static readonly Action _unsuccessfulHttpResponse = - LoggerMessage.Define(LogLevel.Warning, new EventId(2, "UnsuccessfulHttpResponse"), "Unsuccessful HTTP response status code of {StatusCode} return from {RequestMethod} '{RequestUrl}'."); + private static readonly Action _unsuccessfulHttpResponse = + LoggerMessage.Define(LogLevel.Warning, new EventId(2, "UnsuccessfulHttpResponse"), "Unsuccessful HTTP response {StatusCode} return from {RequestMethod} '{RequestUrl}'."); public static void SendingHttpRequest(ILogger logger, HttpMethod requestMethod, Uri requestUrl) { @@ -52,7 +52,7 @@ namespace Microsoft.AspNetCore.Http.Connections.Client.Internal } 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 index 13df2672c6..29067a65b5 100644 --- 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 @@ namespace Microsoft.AspNetCore.Http.Connections.Internal.Transports private static readonly Action _sendFailed = LoggerMessage.Define(LogLevel.Error, new EventId(13, "SendFailed"), "Socket failed to send."); + private static readonly Action _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 @@ namespace Microsoft.AspNetCore.Http.Connections.Internal.Transports _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 index 82e091b5b5..b3c7126834 100644 --- a/src/Microsoft.AspNetCore.Http.Connections/Internal/Transports/WebSocketsTransport.cs +++ b/src/Microsoft.AspNetCore.Http.Connections/Internal/Transports/WebSocketsTransport.cs @@ -182,6 +182,11 @@ namespace Microsoft.AspNetCore.Http.Connections.Internal.Transports } } } + 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 index 0121d2577f..85cff50b24 100644 --- a/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Client.FunctionalTests/HubConnectionTests.cs @@ -5,7 +5,6 @@ using System; using System.Collections.Generic; using System.Linq; using System.Net.Http; -using System.Runtime.CompilerServices; using System.Threading; using System.Threading.Channels; using System.Threading.Tasks; @@ -23,25 +22,18 @@ using Xunit.Abstractions; namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { - [CollectionDefinition(Name)] + // Disable running server tests in parallel so server logs can accurately be captured per test + [CollectionDefinition(Name, DisableParallelization = true)] public class HubConnectionTestsCollection : ICollectionFixture> { - public const string Name = "EndToEndTests"; + public const string Name = nameof(HubConnectionTestsCollection); } [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) - { - throw new ArgumentNullException(nameof(serverFixture)); - } - - _serverFixture = serverFixture; } private HubConnection CreateHubConnection( @@ -66,7 +58,7 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { return async format => { - var connection = new HttpConnection(new Uri(_serverFixture.Url + path), transportType, loggerFactory); + var connection = new HttpConnection(new Uri(ServerFixture.Url + path), transportType, loggerFactory); await connection.StartAsync(format); return connection; }; @@ -81,7 +73,7 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { var connectionBuilder = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) - .WithUrl(_serverFixture.Url + path, transportType); + .WithUrl(ServerFixture.Url + path, transportType); connectionBuilder.Services.AddSingleton(protocol); var connection = connectionBuilder.Build(); @@ -436,8 +428,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.Internal.DefaultHubDispatcher" && + 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 +462,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.Internal.DefaultHubDispatcher" && + 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 +495,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.Internal.DefaultHubDispatcher" && + 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 +528,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.Internal.DefaultHubDispatcher" && + 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 +561,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.Internal.DefaultHubDispatcher" && + 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 +595,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.Internal.DefaultHubDispatcher" && + 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 +630,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.Internal.DefaultHubDispatcher" && + 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 +664,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.Internal.DefaultHubDispatcher" && + 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 +697,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.Internal.DefaultHubDispatcher" && + 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 +730,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.Internal.DefaultHubDispatcher" && + 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 @@ -715,14 +767,14 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { async Task AccessTokenProvider() { - var httpResponse = await new HttpClient().GetAsync(_serverFixture.Url + "/generateJwtToken"); + var httpResponse = await new HttpClient().GetAsync(ServerFixture.Url + "/generateJwtToken"); httpResponse.EnsureSuccessStatusCode(); return await httpResponse.Content.ReadAsStringAsync(); }; var hubConnection = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) - .WithUrl(_serverFixture.Url + "/authorizedhub", transportType, options => + .WithUrl(ServerFixture.Url + "/authorizedhub", transportType, options => { options.AccessTokenProvider = AccessTokenProvider; }) @@ -753,7 +805,7 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { var hubConnection = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) - .WithUrl(_serverFixture.Url + "/default", transportType, options => + .WithUrl(ServerFixture.Url + "/default", transportType, options => { options.Headers["X-test"] = "42"; options.Headers["X-42"] = "test"; @@ -762,8 +814,8 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests try { await hubConnection.StartAsync().OrTimeout(); - var headerValues = await hubConnection.InvokeAsync(nameof(TestHub.GetHeaderValues), new[] { "X-test", "X-42" }).OrTimeout(); - Assert.Equal(new[] { "42", "test" }, headerValues); + var headerValues = await hubConnection.InvokeAsync(nameof(TestHub.GetHeaderValues), new[] {"X-test", "X-42"}).OrTimeout(); + Assert.Equal(new[] {"42", "test"}, headerValues); } catch (Exception ex) { @@ -785,11 +837,11 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { // System.Net has a HttpTransportType type which means we need to fully-qualify this rather than 'use' the namespace var cookieJar = new System.Net.CookieContainer(); - cookieJar.Add(new System.Net.Cookie("Foo", "Bar", "/", new Uri(_serverFixture.Url).Host)); + cookieJar.Add(new System.Net.Cookie("Foo", "Bar", "/", new Uri(ServerFixture.Url).Host)); var hubConnection = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) - .WithUrl(_serverFixture.Url + "/default", HttpTransportType.WebSockets, options => + .WithUrl(ServerFixture.Url + "/default", HttpTransportType.WebSockets, options => { options.WebSocketConfiguration = o => o.Cookies = cookieJar; }) @@ -820,7 +872,7 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests { var hubConnection = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) - .WithUrl(_serverFixture.Url + "/default", transportType) + .WithUrl(ServerFixture.Url + "/default", transportType) .Build(); try { @@ -857,7 +909,7 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests var hubConnectionBuilder = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) .AddMessagePackProtocol() - .WithUrl(_serverFixture.Url + "/default-nowebsockets"); + .WithUrl(ServerFixture.Url + "/default-nowebsockets"); var hubConnection = hubConnectionBuilder.Build(); try @@ -887,7 +939,7 @@ namespace Microsoft.AspNetCore.SignalR.Client.FunctionalTests PollTrackingMessageHandler pollTracker = null; var hubConnection = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) - .WithUrl(_serverFixture.Url + "/default", options => + .WithUrl(ServerFixture.Url + "/default", options => { options.Transports = HttpTransportType.LongPolling; options.HttpMessageHandlerFactory = handler => diff --git a/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs b/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs index 5f1ad5a929..3071d7ab91 100644 --- a/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs +++ b/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs @@ -17,13 +17,14 @@ using Xunit.Abstractions; namespace Microsoft.AspNetCore.SignalR.Redis.Tests { - [CollectionDefinition(Name)] - public class EndToEndTestsCollection : ICollectionFixture> + // Disable running server tests in parallel so server logs can accurately be captured per test + [CollectionDefinition(Name, DisableParallelization = true)] + public class RedisEndToEndTestsCollection : ICollectionFixture> { - public const string Name = "RedisEndToEndTests"; + public const string Name = nameof(RedisEndToEndTestsCollection); } - [Collection(EndToEndTestsCollection.Name)] + [Collection(RedisEndToEndTestsCollection.Name)] public class RedisEndToEndTests : VerifiableLoggedTest { private readonly RedisServerFixture _serverFixture; diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs index 462201fd75..952a29ef83 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs @@ -18,7 +18,18 @@ using Microsoft.Extensions.Logging.Testing; namespace Microsoft.AspNetCore.SignalR.Tests { - public class ServerFixture : IDisposable + public abstract class ServerFixture : IDisposable + { + internal abstract event Action ServerLogged; + + public abstract string WebSocketsUrl { get; } + + public abstract string Url { get; } + + public abstract void Dispose(); + } + + public class ServerFixture : ServerFixture where TStartup : class { private readonly ILoggerFactory _loggerFactory; @@ -28,10 +39,17 @@ namespace Microsoft.AspNetCore.SignalR.Tests private readonly IDisposable _logToken; private readonly LogSinkProvider _logSinkProvider; + private string _url; - public string WebSocketsUrl => Url.Replace("http", "ws"); + internal override event Action ServerLogged + { + add => _logSinkProvider.RecordLogged += value; + remove => _logSinkProvider.RecordLogged -= value; + } - public string Url { get; private set; } + public override string WebSocketsUrl => Url.Replace("http", "ws"); + + public override string Url => _url; public ServerFixture() : this(loggerFactory: null) { @@ -64,7 +82,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests _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 @@ namespace Microsoft.AspNetCore.SignalR.Tests _logger.LogInformation("Test Server started"); // Get the URL from the server - Url = _host.ServerFeatures.Get().Addresses.Single(); + _url = _host.ServerFeatures.Get().Addresses.Single(); _lifetime.ApplicationStopped.Register(() => { @@ -119,7 +137,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests return builder.ToString(); } - public void Dispose() + public override void Dispose() { _logger.LogInformation("Shutting down test server"); _host.Dispose(); @@ -151,6 +169,8 @@ namespace Microsoft.AspNetCore.SignalR.Tests { private readonly ConcurrentQueue _logs = new ConcurrentQueue(); + public event Action RecordLogged; + public ILogger CreateLogger(string categoryName) { return new LogSinkLogger(categoryName, this); @@ -176,6 +196,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/ServerLogScope.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerLogScope.cs new file mode 100644 index 0000000000..8ca3281e98 --- /dev/null +++ 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 _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(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(); + } + } +} \ No newline at end of file diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs index 1968f3bcdd..061823836c 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableLoggedTest.cs @@ -17,14 +17,14 @@ namespace Microsoft.AspNetCore.SignalR.Tests { } - 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.Utils/VerifiableServerLoggedTest.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/VerifiableServerLoggedTest.cs new file mode 100644 index 0000000000..1035116e6a --- /dev/null +++ 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 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 expectedErrorsFilter = null) + { + var disposable = base.StartVerifableLog(out loggerFactory, testName, expectedErrorsFilter); + return new ServerLogScope(ServerFixture, loggerFactory, disposable); + } + } +} \ No newline at end of file diff --git a/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs b/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs index d77ba5e2ff..62b5fedddf 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs @@ -27,25 +27,18 @@ using HttpConnectionOptions = Microsoft.AspNetCore.Http.Connections.Client.HttpC namespace Microsoft.AspNetCore.SignalR.Tests { - [CollectionDefinition(Name)] + // Disable running server tests in parallel so server logs can accurately be captured per test + [CollectionDefinition(Name, DisableParallelization = true)] public class EndToEndTestsCollection : ICollectionFixture> { - public const string Name = "EndToEndTests"; + public const string Name = nameof(EndToEndTestsCollection); } [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) - { - throw new ArgumentNullException(nameof(serverFixture)); - } - - _serverFixture = serverFixture; } [Fact] @@ -53,7 +46,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests { using (StartVerifableLog(out var loggerFactory)) { - var url = _serverFixture.Url + "/echo"; + var url = ServerFixture.Url + "/echo"; // The test should connect to the server using WebSockets transport on Windows 8 and newer. // On Windows 7/2008R2 it should use ServerSentEvents transport to connect to the server. var connection = new HttpConnection(new Uri(url), HttpTransports.All, loggerFactory); @@ -73,7 +66,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests using (StartVerifableLog(out var loggerFactory, expectedErrorsFilter: ExpectedErrors)) { - var url = _serverFixture.Url + "/echo"; + var url = ServerFixture.Url + "/echo"; // The test should connect to the server using WebSockets transport on Windows 8 and newer. // On Windows 7/2008R2 it should use ServerSentEvents transport to connect to the server. @@ -90,7 +83,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests { using (StartVerifableLog(out var loggerFactory, minLogLevel: LogLevel.Trace, testName: $"CanStartAndStopConnectionUsingGivenTransport_{transportType}")) { - var url = _serverFixture.Url + "/echo"; + var url = ServerFixture.Url + "/echo"; var connection = new HttpConnection(new Uri(url), transportType, loggerFactory); await connection.StartAsync(TransferFormat.Text).OrTimeout(); await connection.DisposeAsync().OrTimeout(); @@ -108,7 +101,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests const string message = "Hello, World!"; using (var ws = new ClientWebSocket()) { - var socketUrl = _serverFixture.WebSocketsUrl + "/echo"; + var socketUrl = ServerFixture.WebSocketsUrl + "/echo"; logger.LogInformation("Connecting WebSocket to {socketUrl}", socketUrl); await ws.ConnectAsync(new Uri(socketUrl), CancellationToken.None).OrTimeout(); @@ -145,7 +138,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests const string message = "Hello, World!"; using (var ws = new ClientWebSocket()) { - var socketUrl = _serverFixture.WebSocketsUrl + "/echo"; + var socketUrl = ServerFixture.WebSocketsUrl + "/echo"; logger.LogInformation("Connecting WebSocket to {socketUrl}", socketUrl); await ws.ConnectAsync(new Uri(socketUrl), CancellationToken.None).OrTimeout(); @@ -179,7 +172,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests using (StartVerifableLog(out var loggerFactory)) { var logger = loggerFactory.CreateLogger(); - var url = _serverFixture.Url + "/echo"; + var url = ServerFixture.Url + "/echo"; var mockHttpHandler = new Mock(); mockHttpHandler.Protected() @@ -230,7 +223,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests const string message = "Major Key"; - var url = _serverFixture.Url + "/echo"; + var url = ServerFixture.Url + "/echo"; var connection = new HttpConnection(new Uri(url), transportType, loggerFactory); try { @@ -292,7 +285,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests { var logger = loggerFactory.CreateLogger(); - var url = _serverFixture.Url + "/echo"; + var url = ServerFixture.Url + "/echo"; var connection = new HttpConnection(new Uri(url), HttpTransportType.WebSockets, loggerFactory); try @@ -340,7 +333,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests { var logger = loggerFactory.CreateLogger(); - var url = _serverFixture.Url + "/auth"; + var url = ServerFixture.Url + "/auth"; var connection = new HttpConnection(new Uri(url), HttpTransportType.WebSockets, loggerFactory); try @@ -379,7 +372,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests { var logger = loggerFactory.CreateLogger(); - var url = _serverFixture.Url + "/auth"; + var url = ServerFixture.Url + "/auth"; var connection = new HttpConnection(new Uri(url), transportType, loggerFactory); try @@ -436,7 +429,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests { var logger = loggerFactory.CreateLogger(); - var url = _serverFixture.Url + "/uncreatable"; + var url = ServerFixture.Url + "/uncreatable"; var connection = new HubConnectionBuilder() .WithLoggerFactory(loggerFactory) .WithUrl(url, transportType) diff --git a/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs b/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs index 18c3d64437..90dc73b020 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests/WebSocketsTransportTests.cs @@ -3,7 +3,6 @@ using System; using System.Buffers; -using System.IO.Pipelines; using System.Net; using System.Net.WebSockets; using System.Reflection; @@ -14,7 +13,6 @@ using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Http.Connections.Client; using Microsoft.AspNetCore.Http.Connections.Client.Internal; using Microsoft.AspNetCore.Testing.xunit; -using Microsoft.Extensions.Logging.Testing; using Moq; using Xunit; using Xunit.Abstractions; @@ -22,18 +20,10 @@ 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) - { - throw new ArgumentNullException(nameof(serverFixture)); - } - - _serverFixture = serverFixture; } [ConditionalFact] @@ -70,7 +60,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests using (StartVerifableLog(out var loggerFactory)) { var webSocketsTransport = new WebSocketsTransport(httpConnectionOptions: null, loggerFactory: loggerFactory); - await webSocketsTransport.StartAsync(new Uri(_serverFixture.WebSocketsUrl + "/echo"), + await webSocketsTransport.StartAsync(new Uri(ServerFixture.WebSocketsUrl + "/echo"), TransferFormat.Binary).OrTimeout(); await webSocketsTransport.StopAsync().OrTimeout(); await webSocketsTransport.Running.OrTimeout(); @@ -84,7 +74,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests using (StartVerifableLog(out var loggerFactory)) { var webSocketsTransport = new WebSocketsTransport(httpConnectionOptions: null, loggerFactory: loggerFactory); - await webSocketsTransport.StartAsync(new Uri(_serverFixture.WebSocketsUrl + "/httpheader"), + await webSocketsTransport.StartAsync(new Uri(ServerFixture.WebSocketsUrl + "/httpheader"), TransferFormat.Binary).OrTimeout(); await webSocketsTransport.Output.WriteAsync(Encoding.UTF8.GetBytes("User-Agent")); @@ -112,7 +102,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests using (StartVerifableLog(out var loggerFactory)) { var webSocketsTransport = new WebSocketsTransport(httpConnectionOptions: null, loggerFactory: loggerFactory); - await webSocketsTransport.StartAsync(new Uri(_serverFixture.WebSocketsUrl + "/httpheader"), + await webSocketsTransport.StartAsync(new Uri(ServerFixture.WebSocketsUrl + "/httpheader"), TransferFormat.Binary).OrTimeout(); await webSocketsTransport.Output.WriteAsync(Encoding.UTF8.GetBytes("X-Requested-With")); @@ -135,7 +125,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests using (StartVerifableLog(out var loggerFactory)) { var webSocketsTransport = new WebSocketsTransport(httpConnectionOptions: null, loggerFactory: loggerFactory); - await webSocketsTransport.StartAsync(new Uri(_serverFixture.WebSocketsUrl + "/echo"), + await webSocketsTransport.StartAsync(new Uri(ServerFixture.WebSocketsUrl + "/echo"), TransferFormat.Binary); webSocketsTransport.Output.Complete(); await webSocketsTransport.Running.OrTimeout(TimeSpan.FromSeconds(10)); @@ -151,7 +141,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests using (StartVerifableLog(out var loggerFactory)) { var webSocketsTransport = new WebSocketsTransport(httpConnectionOptions: null, loggerFactory: loggerFactory); - await webSocketsTransport.StartAsync(new Uri(_serverFixture.WebSocketsUrl + "/echoAndClose"), transferFormat); + await webSocketsTransport.StartAsync(new Uri(ServerFixture.WebSocketsUrl + "/echoAndClose"), transferFormat); await webSocketsTransport.Output.WriteAsync(new byte[] { 0x42 }); @@ -174,7 +164,7 @@ namespace Microsoft.AspNetCore.SignalR.Tests { var webSocketsTransport = new WebSocketsTransport(httpConnectionOptions: null, loggerFactory: loggerFactory); - await webSocketsTransport.StartAsync(new Uri(_serverFixture.WebSocketsUrl + "/echo"), + await webSocketsTransport.StartAsync(new Uri(ServerFixture.WebSocketsUrl + "/echo"), transferFormat).OrTimeout(); await webSocketsTransport.StopAsync().OrTimeout();