From a0c47c0c664a1e6c5b1bc669592d25bb4e68d186 Mon Sep 17 00:00:00 2001 From: Andrew Stanton-Nurse Date: Tue, 6 Feb 2018 08:41:16 -0800 Subject: [PATCH] Increase ServerFixture startup timeout (#1409) --- .../LogRecord.cs | 21 ++ .../ServerFixture.cs | 185 ++++++++++-------- .../EndToEndTests.cs | 2 - .../Startup.cs | 2 +- 4 files changed, 122 insertions(+), 88 deletions(-) create mode 100644 test/Microsoft.AspNetCore.SignalR.Tests.Utils/LogRecord.cs diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/LogRecord.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/LogRecord.cs new file mode 100644 index 0000000000..9193044270 --- /dev/null +++ b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/LogRecord.cs @@ -0,0 +1,21 @@ +// 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 Microsoft.Extensions.Logging.Testing; + +namespace Microsoft.AspNetCore.SignalR.Tests +{ + // WriteContext, but with a timestamp... + internal class LogRecord + { + public DateTime Timestamp { get; } + public WriteContext Write { get; } + + public LogRecord(DateTime timestamp, WriteContext write) + { + Timestamp = timestamp; + Write = write; + } + } +} diff --git a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs index bedc092b18..822772e244 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests.Utils/ServerFixture.cs @@ -2,15 +2,18 @@ // 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 System.Collections.Generic; using System.IO; +using System.Linq; using System.Net; using System.Net.Sockets; -using System.Threading; +using System.Text; using System.Threading.Tasks; using Microsoft.AspNetCore.Hosting; +using Microsoft.AspNetCore.Hosting.Server.Features; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Logging.Testing; namespace Microsoft.AspNetCore.SignalR.Tests @@ -23,7 +26,8 @@ namespace Microsoft.AspNetCore.SignalR.Tests private IWebHost _host; private IApplicationLifetime _lifetime; private readonly IDisposable _logToken; - private AsyncForwardingLoggerProvider _asyncLoggerProvider; + + private readonly LogSinkProvider _logSinkProvider; public string WebSocketsUrl => Url.Replace("http", "ws"); @@ -31,27 +35,24 @@ namespace Microsoft.AspNetCore.SignalR.Tests public ServerFixture() { - _asyncLoggerProvider = new AsyncForwardingLoggerProvider(); + _logSinkProvider = new LogSinkProvider(); var testLog = AssemblyTestLog.ForAssembly(typeof(TStartup).Assembly); _logToken = testLog.StartTestLog(null, $"{nameof(ServerFixture)}_{typeof(TStartup).Name}", out _loggerFactory, "ServerFixture"); - _loggerFactory.AddProvider(_asyncLoggerProvider); _logger = _loggerFactory.CreateLogger>(); + + StartServer(); + } + + private void StartServer() + { // We're using 127.0.0.1 instead of localhost to ensure that we use IPV4 across different OSes - Url = "http://127.0.0.1:" + GetNextPort(); + var url = "http://127.0.0.1:0"; - StartServer(Url); - } - - public void SetTestLoggerFactory(ILoggerFactory loggerFactory) - { - _asyncLoggerProvider.SetLoggerFactory(loggerFactory); - } - - private void StartServer(string url) - { _host = new WebHostBuilder() - .ConfigureLogging(builder => builder.AddProvider(new ForwardingLoggerProvider(_loggerFactory))) + .ConfigureLogging(builder => builder + .AddProvider(_logSinkProvider) + .AddProvider(new ForwardingLoggerProvider(_loggerFactory))) .UseStartup(typeof(TStartup)) .UseKestrel() .UseUrls(url) @@ -61,17 +62,24 @@ namespace Microsoft.AspNetCore.SignalR.Tests var t = Task.Run(() => _host.Start()); _logger.LogInformation("Starting test server..."); _lifetime = _host.Services.GetRequiredService(); - if (!_lifetime.ApplicationStarted.WaitHandle.WaitOne(TimeSpan.FromSeconds(5))) + + // This only happens once per fixture, so we can afford to wait a little bit on it. + if (!_lifetime.ApplicationStarted.WaitHandle.WaitOne(TimeSpan.FromSeconds(20))) { // t probably faulted if (t.IsFaulted) { throw t.Exception.InnerException; } - throw new TimeoutException("Timed out waiting for application to start."); + + var logs = _logSinkProvider.GetLogs(); + throw new TimeoutException($"Timed out waiting for application to start.{Environment.NewLine}Startup Logs:{Environment.NewLine}{RenderLogs(logs)}"); } _logger.LogInformation("Test Server started"); + // Get the URL from the server + Url = _host.ServerFeatures.Get().Addresses.Single(); + _lifetime.ApplicationStopped.Register(() => { _logger.LogInformation("Test server shut down"); @@ -79,6 +87,24 @@ namespace Microsoft.AspNetCore.SignalR.Tests }); } + private string RenderLogs(IList logs) + { + var builder = new StringBuilder(); + foreach (var log in logs) + { + builder.AppendLine($"{log.Timestamp:O} {log.Write.LoggerName} {log.Write.LogLevel}: {log.Write.Formatter(log.Write.State, log.Write.Exception)}"); + if (log.Write.Exception != null) + { + var message = log.Write.Exception.ToString(); + foreach (var line in message.Split(new[] { Environment.NewLine }, StringSplitOptions.None)) + { + builder.AppendLine($"| {line}"); + } + } + } + return builder.ToString(); + } + public void Dispose() { _logger.LogInformation("Shutting down test server"); @@ -86,62 +112,6 @@ namespace Microsoft.AspNetCore.SignalR.Tests _loggerFactory.Dispose(); } - private class AsyncForwardingLoggerProvider : ILoggerProvider - { - private AsyncLocal _localLogger = new AsyncLocal(); - - public ILogger CreateLogger(string categoryName) - { - return new AsyncLocalForwardingLogger(categoryName, _localLogger); - } - - public void Dispose() - { - } - - public void SetLoggerFactory(ILoggerFactory loggerFactory) - { - _localLogger.Value = loggerFactory; - } - - private class AsyncLocalForwardingLogger : ILogger - { - private string _categoryName; - private AsyncLocal _localLoggerFactory; - - public AsyncLocalForwardingLogger(string categoryName, AsyncLocal localLoggerFactory) - { - _categoryName = categoryName; - _localLoggerFactory = localLoggerFactory; - } - - public IDisposable BeginScope(TState state) - { - return GetLocalLogger().BeginScope(state); - } - - public bool IsEnabled(LogLevel logLevel) - { - return GetLocalLogger().IsEnabled(logLevel); - } - - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) - { - GetLocalLogger().Log(logLevel, eventId, state, exception, formatter); - } - - private ILogger GetLocalLogger() - { - var factory = _localLoggerFactory.Value; - if (factory == null) - { - return NullLogger.Instance; - } - return factory.CreateLogger(_categoryName); - } - } - } - private class ForwardingLoggerProvider : ILoggerProvider { private readonly ILoggerFactory _loggerFactory; @@ -161,18 +131,63 @@ namespace Microsoft.AspNetCore.SignalR.Tests } } - // Copied from https://github.com/aspnet/KestrelHttpServer/blob/47f1db20e063c2da75d9d89653fad4eafe24446c/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/AddressRegistrationTests.cs#L508 - private static int GetNextPort() + // TestSink doesn't seem to be thread-safe :(. + private class LogSinkProvider : ILoggerProvider { - using (var socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp)) + private ConcurrentQueue _logs = new ConcurrentQueue(); + + public ILogger CreateLogger(string categoryName) { - // Let the OS assign the next available port. Unless we cycle through all ports - // on a test run, the OS will always increment the port number when making these calls. - // This prevents races in parallel test runs where a test is already bound to - // a given port, and a new test is able to bind to the same port due to port - // reuse being enabled by default by the OS. - socket.Bind(new IPEndPoint(IPAddress.Loopback, 0)); - return ((IPEndPoint)socket.LocalEndPoint).Port; + return new LogSinkLogger(categoryName, this); + } + + public void Dispose() + { + } + + public IList GetLogs() => _logs.ToList(); + + public void Log(string categoryName, LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + var record = new LogRecord( + DateTime.Now, + new WriteContext() + { + LoggerName = categoryName, + LogLevel = logLevel, + EventId = eventId, + State = state, + Exception = exception, + Formatter = (o, e) => formatter((TState)o, e), + }); + _logs.Enqueue(record); + } + + private class LogSinkLogger : ILogger + { + private string _categoryName; + private LogSinkProvider _logSinkProvider; + + public LogSinkLogger(string categoryName, LogSinkProvider logSinkProvider) + { + _categoryName = categoryName; + _logSinkProvider = logSinkProvider; + } + + public IDisposable BeginScope(TState state) + { + return null; + } + + public bool IsEnabled(LogLevel logLevel) + { + return true; + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _logSinkProvider.Log(_categoryName, logLevel, eventId, state, exception, formatter); + } } } } diff --git a/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs b/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs index c487e98645..eab73d564b 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests/EndToEndTests.cs @@ -326,8 +326,6 @@ namespace Microsoft.AspNetCore.SignalR.Tests { using (StartLog(out var loggerFactory, testName: $"ConnectionCanSendAndReceiveMessages_{transportType.ToString()}")) { - _serverFixture.SetTestLoggerFactory(loggerFactory); - var logger = loggerFactory.CreateLogger(); var url = _serverFixture.Url + "/uncreatable"; diff --git a/test/Microsoft.AspNetCore.SignalR.Tests/Startup.cs b/test/Microsoft.AspNetCore.SignalR.Tests/Startup.cs index 4345ca24d1..714d3602dc 100644 --- a/test/Microsoft.AspNetCore.SignalR.Tests/Startup.cs +++ b/test/Microsoft.AspNetCore.SignalR.Tests/Startup.cs @@ -1,4 +1,4 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// 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 Microsoft.AspNetCore.Builder;