Add test logging helpers to Hosting (#1005)

This commit is contained in:
Andrew Stanton-Nurse 2017-04-06 15:19:26 -07:00 committed by GitHub
parent ad79cdd123
commit 1ae1ff01a3
14 changed files with 329 additions and 86 deletions

View File

@ -11,5 +11,7 @@
<WebAdministrationVersion>7.0.0</WebAdministrationVersion>
<WindowsApiSetsVersion>1.0.1</WindowsApiSetsVersion>
<XunitVersion>2.2.0</XunitVersion>
<SerilogExtensionsLoggingVersion>1.4.0</SerilogExtensionsLoggingVersion>
<SerilogFileSinkVersion>3.2.0</SerilogFileSinkVersion>
</PropertyGroup>
</Project>
</Project>

View File

@ -1,7 +1,10 @@
// 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.Net.Http;
using System.Threading;
using Microsoft.Extensions.Logging;
namespace Microsoft.AspNetCore.Server.IntegrationTesting
{
@ -10,25 +13,57 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
/// </summary>
public class DeploymentResult
{
private readonly ILoggerFactory _loggerFactory;
/// <summary>
/// Base Uri of the deployment application.
/// </summary>
public string ApplicationBaseUri { get; set; }
public string ApplicationBaseUri { get; }
/// <summary>
/// The folder where the application is hosted. This path can be different from the
/// original application source location if published before deployment.
/// </summary>
public string ContentRoot { get; set; }
public string ContentRoot { get; }
/// <summary>
/// Original deployment parameters used for this deployment.
/// </summary>
public DeploymentParameters DeploymentParameters { get; set; }
public DeploymentParameters DeploymentParameters { get; }
/// <summary>
/// Triggered when the host process dies or pulled down.
/// </summary>
public CancellationToken HostShutdownToken { get; set; }
public CancellationToken HostShutdownToken { get; }
/// <summary>
/// An <see cref="HttpClient"/> with <see cref="LoggingHandler"/> configured and the <see cref="HttpClient.BaseAddress"/> set to the <see cref="ApplicationBaseUri"/>
/// </summary>
public HttpClient HttpClient { get; }
public DeploymentResult(ILoggerFactory loggerFactory, DeploymentParameters deploymentParameters, string applicationBaseUri)
: this(loggerFactory, deploymentParameters: deploymentParameters, applicationBaseUri: applicationBaseUri, contentRoot: string.Empty, hostShutdownToken: CancellationToken.None)
{ }
public DeploymentResult(ILoggerFactory loggerFactory, DeploymentParameters deploymentParameters, string applicationBaseUri, string contentRoot, CancellationToken hostShutdownToken)
{
_loggerFactory = loggerFactory;
ApplicationBaseUri = applicationBaseUri;
ContentRoot = contentRoot;
DeploymentParameters = deploymentParameters;
HostShutdownToken = hostShutdownToken;
HttpClient = CreateHttpClient(new HttpClientHandler());
}
/// <summary>
/// Create an <see cref="HttpClient"/> with <see cref="LoggingHandler"/> configured and the <see cref="HttpClient.BaseAddress"/> set to the <see cref="ApplicationBaseUri"/>,
/// but using the provided <see cref="HttpMessageHandler"/> and the underlying handler.
/// </summary>
/// <param name="baseHandler"></param>
/// <returns></returns>
public HttpClient CreateHttpClient(HttpMessageHandler baseHandler) =>
new HttpClient(new LoggingHandler(_loggerFactory, baseHandler)) { BaseAddress = new Uri(ApplicationBaseUri) };
}
}

View File

@ -0,0 +1,34 @@
using System;
using System.Net.Http;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
namespace Microsoft.AspNetCore.Server.IntegrationTesting
{
internal class LoggingHandler : DelegatingHandler
{
private ILogger _logger;
public LoggingHandler(ILoggerFactory loggerFactory, HttpMessageHandler innerHandler) : base(innerHandler)
{
_logger = loggerFactory.CreateLogger<HttpClient>();
}
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
_logger.LogDebug("Sending {method} {url}", request.Method, request.RequestUri);
try
{
var response = await base.SendAsync(request, cancellationToken);
_logger.LogDebug("Received {statusCode} {reasonPhrase} {url}", response.StatusCode, response.ReasonPhrase, request.RequestUri);
return response;
}
catch (Exception ex)
{
_logger.LogError(0, ex, "Exception while sending '{method} {url}'", request.Method, request.RequestUri, request.RequestUri);
throw;
}
}
}
}

View File

@ -14,7 +14,7 @@ namespace System.Diagnostics
{
if (!string.IsNullOrEmpty(dataArgs.Data))
{
logger.LogWarning($"{prefix} stdout: {{line}}", dataArgs.Data);
logger.LogInformation($"{prefix} stdout: {{line}}", dataArgs.Data);
}
};

View File

@ -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 System;
@ -59,7 +59,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
if (exception is HttpRequestException
#if NET46
|| exception is System.Net.WebException
#elif NETSTANDARD1_3
#elif NETSTANDARD1_5
#else
#error Target frameworks need to be updated.
#endif

View File

@ -26,14 +26,16 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
private readonly Stopwatch _stopwatch = new Stopwatch();
public ApplicationDeployer(DeploymentParameters deploymentParameters, ILogger logger)
public ApplicationDeployer(DeploymentParameters deploymentParameters, ILoggerFactory loggerFactory)
{
DeploymentParameters = deploymentParameters;
Logger = logger;
LoggerFactory = loggerFactory;
Logger = LoggerFactory.CreateLogger(GetType().FullName);
}
protected DeploymentParameters DeploymentParameters { get; }
protected ILoggerFactory LoggerFactory { get; }
protected ILogger Logger { get; }
public abstract Task<DeploymentResult> DeployAsync();

View File

@ -32,14 +32,14 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
switch (deploymentParameters.ServerType)
{
case ServerType.IISExpress:
return new IISExpressDeployer(deploymentParameters, loggerFactory.CreateLogger<IISExpressDeployer>());
return new IISExpressDeployer(deploymentParameters, loggerFactory);
case ServerType.IIS:
throw new NotSupportedException("The IIS deployer is no longer supported");
case ServerType.WebListener:
case ServerType.Kestrel:
return new SelfHostDeployer(deploymentParameters, loggerFactory.CreateLogger<SelfHostDeployer>());
return new SelfHostDeployer(deploymentParameters, loggerFactory);
case ServerType.Nginx:
return new NginxDeployer(deploymentParameters, loggerFactory.CreateLogger<NginxDeployer>());
return new NginxDeployer(deploymentParameters, loggerFactory);
default:
throw new NotSupportedException(
string.Format("Found no deployers suitable for server type '{0}' with the current runtime.",

View File

@ -28,8 +28,8 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
private Process _hostProcess;
public IISExpressDeployer(DeploymentParameters deploymentParameters, ILogger logger)
: base(deploymentParameters, logger)
public IISExpressDeployer(DeploymentParameters deploymentParameters, ILoggerFactory loggerFactory)
: base(deploymentParameters, loggerFactory)
{
}
@ -75,14 +75,13 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
Logger.LogInformation("Application ready at URL: {appUrl}", actualUri);
return new DeploymentResult
{
ContentRoot = contentRoot,
DeploymentParameters = DeploymentParameters,
// Right now this works only for urls like http://localhost:5001/. Does not work for http://localhost:5001/subpath.
ApplicationBaseUri = actualUri.ToString(),
HostShutdownToken = hostExitToken
};
// Right now this works only for urls like http://localhost:5001/. Does not work for http://localhost:5001/subpath.
return new DeploymentResult(
LoggerFactory,
DeploymentParameters,
applicationBaseUri: actualUri.ToString(),
contentRoot: contentRoot,
hostShutdownToken: hostExitToken);
}
}

View File

@ -19,8 +19,8 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
private string _configFile;
private readonly int _waitTime = (int)TimeSpan.FromSeconds(30).TotalMilliseconds;
public NginxDeployer(DeploymentParameters deploymentParameters, ILogger logger)
: base(deploymentParameters, logger)
public NginxDeployer(DeploymentParameters deploymentParameters, ILoggerFactory loggerFactory)
: base(deploymentParameters, loggerFactory)
{
}
@ -61,13 +61,12 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
}
}
return new DeploymentResult
{
ContentRoot = DeploymentParameters.ApplicationPath,
DeploymentParameters = DeploymentParameters,
ApplicationBaseUri = uri.ToString(),
HostShutdownToken = exitToken
};
return new DeploymentResult(
LoggerFactory,
DeploymentParameters,
applicationBaseUri: uri.ToString(),
contentRoot: DeploymentParameters.ApplicationPath,
hostShutdownToken: exitToken);
}
}

View File

@ -26,8 +26,8 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
private bool _isDisposed;
private static readonly Lazy<Scripts> _scripts = new Lazy<Scripts>(() => CopyEmbeddedScriptFilesToDisk());
public RemoteWindowsDeployer(RemoteWindowsDeploymentParameters deploymentParameters, ILogger logger)
: base(deploymentParameters, logger)
public RemoteWindowsDeployer(RemoteWindowsDeploymentParameters deploymentParameters, ILoggerFactory loggerFactory)
: base(deploymentParameters, loggerFactory)
{
_deploymentParameters = deploymentParameters;
@ -103,11 +103,10 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
await RunScriptAsync("StartServer");
return new DeploymentResult
{
ApplicationBaseUri = DeploymentParameters.ApplicationBaseUriHint,
DeploymentParameters = DeploymentParameters
};
return new DeploymentResult(
LoggerFactory,
DeploymentParameters,
DeploymentParameters.ApplicationBaseUriHint);
}
}

View File

@ -24,8 +24,8 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
public Process HostProcess { get; private set; }
public SelfHostDeployer(DeploymentParameters deploymentParameters, ILogger logger)
: base(deploymentParameters, logger)
public SelfHostDeployer(DeploymentParameters deploymentParameters, ILoggerFactory loggerFactory)
: base(deploymentParameters, loggerFactory)
{
}
@ -48,13 +48,12 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting
Logger.LogInformation("Application ready at URL: {appUrl}", actualUrl);
return new DeploymentResult
{
ContentRoot = DeploymentParameters.PublishApplicationBeforeDeployment ? DeploymentParameters.PublishedApplicationRootPath : DeploymentParameters.ApplicationPath,
DeploymentParameters = DeploymentParameters,
ApplicationBaseUri = actualUrl.ToString(),
HostShutdownToken = hostExitToken
};
return new DeploymentResult(
LoggerFactory,
DeploymentParameters,
applicationBaseUri: actualUrl.ToString(),
contentRoot: DeploymentParameters.PublishApplicationBeforeDeployment ? DeploymentParameters.PublishedApplicationRootPath : DeploymentParameters.ApplicationPath,
hostShutdownToken: hostExitToken);
}
}

View File

@ -5,7 +5,7 @@
<PropertyGroup>
<Description>ASP.NET Core helpers to deploy applications to IIS Express, IIS, WebListener and Kestrel for testing.</Description>
<VersionPrefix>0.4.0</VersionPrefix>
<TargetFrameworks>net46;netstandard1.3</TargetFrameworks>
<TargetFrameworks>net46;netstandard1.5</TargetFrameworks>
<NoWarn>$(NoWarn);CS1591</NoWarn>
<GenerateDocumentationFile>true</GenerateDocumentationFile>
<PackageTags>aspnetcore;testing</PackageTags>
@ -20,11 +20,15 @@
<PackageReference Include="System.ValueTuple" Version="$(CoreFxVersion)" />
<PackageReference Include="Microsoft.AspNetCore.Testing" Version="$(AspNetCoreVersion)" />
<PackageReference Include="Microsoft.Extensions.FileProviders.Embedded" Version="$(AspNetCoreVersion)" />
<PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="$(AspNetCoreVersion)" />
<PackageReference Include="Microsoft.Extensions.Logging" Version="$(AspNetCoreVersion)" />
<PackageReference Include="Microsoft.Extensions.Logging.Console" Version="$(AspNetCoreVersion)" />
<PackageReference Include="Microsoft.Extensions.Logging.Testing" Version="$(AspNetCoreVersion)" />
<PackageReference Include="Microsoft.Extensions.PlatformAbstractions" Version="$(AspNetCoreVersion)" />
<PackageReference Include="Microsoft.Extensions.Process.Sources" Version="$(AspNetCoreVersion)" PrivateAssets="All" />
<PackageReference Include="Microsoft.Extensions.RuntimeEnvironment.Sources" Version="$(AspNetCoreVersion)" PrivateAssets="All" />
<PackageReference Include="Microsoft.NETCore.Windows.ApiSets" Version="$(WindowsApiSetsVersion)" />
<PackageReference Include="Serilog.Extensions.Logging" Version="$(SerilogExtensionsLoggingVersion)" />
<PackageReference Include="Serilog.Sinks.File" Version="$(SerilogFileSinkVersion)" />
</ItemGroup>
<ItemGroup Condition=" '$(TargetFramework)' == 'net46' ">
@ -33,7 +37,7 @@
<Reference Include="System.Xml.Linq" />
</ItemGroup>
<ItemGroup Condition=" '$(TargetFramework)' == 'netstandard1.3' ">
<ItemGroup Condition=" '$(TargetFramework)' == 'netstandard1.5' ">
<PackageReference Include="System.Diagnostics.Process" Version="$(CoreFxVersion)" />
<PackageReference Include="System.Threading.Thread" Version="$(CoreFxVersion)" />
</ItemGroup>

View File

@ -0,0 +1,166 @@
// 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.Diagnostics;
using System.IO;
using System.Reflection;
using System.Runtime.CompilerServices;
using Microsoft.Extensions.Logging;
using Serilog;
using Xunit.Abstractions;
namespace Microsoft.AspNetCore.Server.IntegrationTesting.xunit
{
public static class TestLogging
{
// Need to qualify because of Serilog.ILogger :(
private static readonly object _initLock = new object();
private volatile static Extensions.Logging.ILogger GlobalLogger = null;
public static readonly string OutputDirectoryEnvironmentVariableName = "ASPNETCORE_TEST_LOG_DIR";
public static readonly string TestOutputRoot;
static TestLogging()
{
TestOutputRoot = Environment.GetEnvironmentVariable(OutputDirectoryEnvironmentVariableName);
}
public static IDisposable Start<TTestClass>(ITestOutputHelper output, out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null) =>
Start(output, out loggerFactory, typeof(TTestClass).GetTypeInfo().Assembly.GetName().Name, typeof(TTestClass).FullName, testName);
public static IDisposable Start(ITestOutputHelper output, out ILoggerFactory loggerFactory, string appName, string className, [CallerMemberName] string testName = null)
{
EnsureGlobalLoggingInitialized(appName);
var factory = CreateLoggerFactory(output, appName, className, testName);
loggerFactory = factory;
var logger = factory.CreateLogger("TestLifetime");
var stopwatch = Stopwatch.StartNew();
GlobalLogger.LogInformation("Starting test {testName}", testName);
logger.LogInformation("Starting test {testName}", testName);
return new Disposable(() =>
{
stopwatch.Stop();
GlobalLogger.LogInformation("Finished test {testName} in {duration}s", testName, stopwatch.Elapsed.TotalSeconds);
logger.LogInformation("Finished test {testName} in {duration}s", testName, stopwatch.Elapsed.TotalSeconds);
factory.Dispose();
});
}
public static ILoggerFactory CreateLoggerFactory<TTestClass>(ITestOutputHelper output, [CallerMemberName] string testName = null) =>
CreateLoggerFactory(output, typeof(TTestClass).GetTypeInfo().Assembly.GetName().Name, typeof(TTestClass).FullName, testName);
public static ILoggerFactory CreateLoggerFactory(ITestOutputHelper output, string appName, string className, [CallerMemberName] string testName = null)
{
var loggerFactory = new LoggerFactory();
loggerFactory.AddXunit(output, LogLevel.Debug);
// Try to shorten the class name using the assembly name
if (className.StartsWith(appName + "."))
{
className = className.Substring(appName.Length + 1);
}
var testOutputFile = Path.Combine(appName, className, $"{testName}.log");
AddFileLogging(loggerFactory, testOutputFile);
return loggerFactory;
}
// Need to qualify because of Serilog.ILogger :(
private static Extensions.Logging.ILogger CreateGlobalLogger(string assemblyName)
{
var loggerFactory = new LoggerFactory();
// Let the global logger log to the console, it's just "Starting X..." "Finished X..."
loggerFactory.AddConsole();
var globalLogFileName = Path.Combine(assemblyName, "global.log");
AddFileLogging(loggerFactory, globalLogFileName);
var logger = loggerFactory.CreateLogger("GlobalTestLog");
logger.LogInformation($"Global Test Logging initialized. Set the '{OutputDirectoryEnvironmentVariableName}' Environment Variable in order to create log files on disk.");
return logger;
}
private static void AddFileLogging(ILoggerFactory loggerFactory, string fileName)
{
if (!string.IsNullOrEmpty(TestOutputRoot))
{
fileName = Path.Combine(TestOutputRoot, fileName);
var dir = Path.GetDirectoryName(fileName);
if (!Directory.Exists(dir))
{
Directory.CreateDirectory(dir);
}
if (File.Exists(fileName))
{
File.Delete(fileName);
}
var serilogger = new LoggerConfiguration()
.Enrich.FromLogContext()
.MinimumLevel.Verbose()
.WriteTo.File(fileName, flushToDiskInterval: TimeSpan.FromSeconds(1))
.CreateLogger();
loggerFactory.AddSerilog(serilogger);
}
}
private static void EnsureGlobalLoggingInitialized(string assemblyName)
{
// Ye olde double-check lock because we need to pass the assembly name in if we are initializing
// so we can't use Lazy<T>
if(GlobalLogger == null)
{
lock(_initLock)
{
if(GlobalLogger == null)
{
GlobalLogger = CreateGlobalLogger(assemblyName);
}
}
}
}
private class Disposable : IDisposable
{
private Action _action;
public Disposable(Action action)
{
_action = action;
}
public void Dispose()
{
_action();
}
}
}
public abstract class LoggedTest
{
private readonly ITestOutputHelper _output;
protected LoggedTest(ITestOutputHelper output)
{
_output = output;
}
public IDisposable StartLog(out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null)
{
return TestLogging.Start(
_output,
out loggerFactory,
GetType().GetTypeInfo().Assembly.GetName().Name,
GetType().FullName,
testName);
}
}
}

View File

@ -7,59 +7,63 @@ using System.Threading.Tasks;
using Microsoft.AspNetCore.Server.IntegrationTesting;
using Microsoft.AspNetCore.Server.IntegrationTesting.xunit;
using Microsoft.AspNetCore.Testing.xunit;
using Microsoft.Extensions.Logging;
using Xunit;
using Xunit.Abstractions;
namespace Microsoft.AspNetCore.Hosting.FunctionalTests
{
public class ShutdownTests
public class ShutdownTests : LoggedTest
{
public ShutdownTests(ITestOutputHelper output) : base(output)
{
}
[ConditionalFact]
[OSSkipCondition(OperatingSystems.Windows)]
[OSSkipCondition(OperatingSystems.MacOSX)]
public async Task ShutdownTest()
{
var logger = new LoggerFactory()
.AddConsole()
.CreateLogger(nameof(ShutdownTest));
logger.LogInformation("Started test: {testName}", nameof(ShutdownTest));
var applicationPath = Path.Combine(TestProjectHelpers.GetSolutionRoot(), "test",
"Microsoft.AspNetCore.Hosting.TestSites");
var deploymentParameters = new DeploymentParameters(
applicationPath,
ServerType.Kestrel,
RuntimeFlavor.CoreClr,
RuntimeArchitecture.x64)
using (StartLog(out var loggerFactory))
{
EnvironmentName = "Shutdown",
TargetFramework = "netcoreapp2.0",
ApplicationType = ApplicationType.Portable,
PublishApplicationBeforeDeployment = true
};
var logger = loggerFactory.CreateLogger(nameof(ShutdownTest));
using (var deployer = new SelfHostDeployer(deploymentParameters, logger))
{
await deployer.DeployAsync();
var applicationPath = Path.Combine(TestProjectHelpers.GetSolutionRoot(), "test",
"Microsoft.AspNetCore.Hosting.TestSites");
// Wait for application to start
await Task.Delay(1000);
var deploymentParameters = new DeploymentParameters(
applicationPath,
ServerType.Kestrel,
RuntimeFlavor.CoreClr,
RuntimeArchitecture.x64)
{
EnvironmentName = "Shutdown",
TargetFramework = "netcoreapp2.0",
ApplicationType = ApplicationType.Portable,
PublishApplicationBeforeDeployment = true
};
string output = string.Empty;
deployer.HostProcess.OutputDataReceived += (sender, args) => output += args.Data + '\n';
using (var deployer = new SelfHostDeployer(deploymentParameters, loggerFactory))
{
await deployer.DeployAsync();
SendSIGINT(deployer.HostProcess.Id);
// Wait for application to start
await Task.Delay(1000);
WaitForExitOrKill(deployer.HostProcess);
string output = string.Empty;
deployer.HostProcess.OutputDataReceived += (sender, args) => output += args.Data + '\n';
output = output.Trim('\n');
SendSIGINT(deployer.HostProcess.Id);
Assert.Equal(output, "Application is shutting down...\n" +
"Stopping firing\n" +
"Stopping end\n" +
"Stopped firing\n" +
"Stopped end");
WaitForExitOrKill(deployer.HostProcess);
output = output.Trim('\n');
Assert.Equal(output, "Application is shutting down...\n" +
"Stopping firing\n" +
"Stopping end\n" +
"Stopped firing\n" +
"Stopped end");
}
}
}