diff --git a/src/Testing/src/AssemblyTestLog.cs b/src/Testing/src/AssemblyTestLog.cs new file mode 100644 index 0000000000..bd69cd20a3 --- /dev/null +++ b/src/Testing/src/AssemblyTestLog.cs @@ -0,0 +1,306 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.IO; +using System.Linq; +using System.Reflection; +using System.Runtime.CompilerServices; +using System.Text; +using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.DependencyInjection; +using Serilog; +using Serilog.Core; +using Serilog.Events; +using Serilog.Extensions.Logging; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing +{ + public class AssemblyTestLog : IDisposable + { + private static readonly string MaxPathLengthEnvironmentVariableName = "ASPNETCORE_TEST_LOG_MAXPATH"; + private static readonly string LogFileExtension = ".log"; + private static readonly int MaxPathLength = GetMaxPathLength(); + + private static readonly object _lock = new object(); + private static readonly Dictionary _logs = new Dictionary(); + + private readonly ILoggerFactory _globalLoggerFactory; + private readonly ILogger _globalLogger; + private readonly string _baseDirectory; + private readonly Assembly _assembly; + private readonly IServiceProvider _serviceProvider; + + private static int GetMaxPathLength() + { + var maxPathString = Environment.GetEnvironmentVariable(MaxPathLengthEnvironmentVariableName); + var defaultMaxPath = 245; + return string.IsNullOrEmpty(maxPathString) ? defaultMaxPath : int.Parse(maxPathString); + } + + private AssemblyTestLog(ILoggerFactory globalLoggerFactory, ILogger globalLogger, string baseDirectory, Assembly assembly, IServiceProvider serviceProvider) + { + _globalLoggerFactory = globalLoggerFactory; + _globalLogger = globalLogger; + _baseDirectory = baseDirectory; + _assembly = assembly; + _serviceProvider = serviceProvider; + } + + public IDisposable StartTestLog(ITestOutputHelper output, string className, out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null) => + StartTestLog(output, className, out loggerFactory, LogLevel.Debug, testName); + + public IDisposable StartTestLog(ITestOutputHelper output, string className, out ILoggerFactory loggerFactory, LogLevel minLogLevel, [CallerMemberName] string testName = null) => + StartTestLog(output, className, out loggerFactory, minLogLevel, out var _, out var _, testName); + + internal IDisposable StartTestLog(ITestOutputHelper output, string className, out ILoggerFactory loggerFactory, LogLevel minLogLevel, out string resolvedTestName, out string logOutputDirectory, [CallerMemberName] string testName = null) + { + var logStart = DateTimeOffset.UtcNow; + var serviceProvider = CreateLoggerServices(output, className, minLogLevel, out resolvedTestName, out logOutputDirectory, testName, logStart); + var factory = serviceProvider.GetRequiredService(); + loggerFactory = factory; + var logger = loggerFactory.CreateLogger("TestLifetime"); + + var stopwatch = Stopwatch.StartNew(); + + var scope = logger.BeginScope("Test: {testName}", testName); + + _globalLogger.LogInformation("Starting test {testName}", testName); + logger.LogInformation("Starting test {testName} at {logStart}", testName, logStart.ToString("s")); + + 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); + scope.Dispose(); + factory.Dispose(); + (serviceProvider as IDisposable)?.Dispose(); + }); + } + + public ILoggerFactory CreateLoggerFactory(ITestOutputHelper output, string className, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) + => CreateLoggerFactory(output, className, LogLevel.Trace, testName, logStart); + + public ILoggerFactory CreateLoggerFactory(ITestOutputHelper output, string className, LogLevel minLogLevel, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) + => CreateLoggerServices(output, className, minLogLevel, out var _, out var _, testName, logStart).GetRequiredService(); + + public IServiceProvider CreateLoggerServices(ITestOutputHelper output, string className, LogLevel minLogLevel, out string normalizedTestName, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) + => CreateLoggerServices(output, className, minLogLevel, out normalizedTestName, out var _, testName, logStart); + + public IServiceProvider CreateLoggerServices(ITestOutputHelper output, string className, LogLevel minLogLevel, out string normalizedTestName, out string logOutputDirectory, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) + { + normalizedTestName = string.Empty; + logOutputDirectory = string.Empty; + var assemblyName = _assembly.GetName().Name; + + // Try to shorten the class name using the assembly name + if (className.StartsWith(assemblyName + ".")) + { + className = className.Substring(assemblyName.Length + 1); + } + + SerilogLoggerProvider serilogLoggerProvider = null; + if (!string.IsNullOrEmpty(_baseDirectory)) + { + logOutputDirectory = Path.Combine(_baseDirectory, className); + testName = TestFileOutputContext.RemoveIllegalFileChars(testName); + + if (logOutputDirectory.Length + testName.Length + LogFileExtension.Length >= MaxPathLength) + { + _globalLogger.LogWarning($"Test name {testName} is too long. Please shorten test name."); + + // Shorten the test name by removing the middle portion of the testname + var testNameLength = MaxPathLength - logOutputDirectory.Length - LogFileExtension.Length; + + if (testNameLength <= 0) + { + throw new InvalidOperationException("Output file path could not be constructed due to max path length restrictions. Please shorten test assembly, class or method names."); + } + + testName = testName.Substring(0, testNameLength / 2) + testName.Substring(testName.Length - testNameLength / 2, testNameLength / 2); + + _globalLogger.LogWarning($"To prevent long paths test name was shortened to {testName}."); + } + + var testOutputFile = Path.Combine(logOutputDirectory, $"{testName}{LogFileExtension}"); + + if (File.Exists(testOutputFile)) + { + _globalLogger.LogWarning($"Output log file {testOutputFile} already exists. Please try to keep log file names unique."); + + for (var i = 0; i < 1000; i++) + { + testOutputFile = Path.Combine(logOutputDirectory, $"{testName}.{i}{LogFileExtension}"); + + if (!File.Exists(testOutputFile)) + { + _globalLogger.LogWarning($"To resolve log file collision, the enumerated file {testOutputFile} will be used."); + testName = $"{testName}.{i}"; + break; + } + } + } + + normalizedTestName = testName; + serilogLoggerProvider = ConfigureFileLogging(testOutputFile, logStart); + } + + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(builder => + { + builder.SetMinimumLevel(minLogLevel); + + if (output != null) + { + builder.AddXunit(output, minLogLevel, logStart); + } + + if (serilogLoggerProvider != null) + { + // Use a factory so that the container will dispose it + builder.Services.AddSingleton(_ => serilogLoggerProvider); + } + }); + + return serviceCollection.BuildServiceProvider(); + } + + // For back compat + public static AssemblyTestLog Create(string assemblyName, string baseDirectory) + => Create(Assembly.Load(new AssemblyName(assemblyName)), baseDirectory); + + public static AssemblyTestLog Create(Assembly assembly, string baseDirectory) + { + var logStart = DateTimeOffset.UtcNow; + SerilogLoggerProvider serilogLoggerProvider = null; + if (!string.IsNullOrEmpty(baseDirectory)) + { + baseDirectory = TestFileOutputContext.GetAssemblyBaseDirectory(assembly, baseDirectory); + var globalLogFileName = Path.Combine(baseDirectory, "global.log"); + serilogLoggerProvider = ConfigureFileLogging(globalLogFileName, logStart); + } + + var serviceCollection = new ServiceCollection(); + + serviceCollection.AddLogging(builder => + { + // Global logging, when it's written, is expected to be outputted. So set the log level to minimum. + builder.SetMinimumLevel(LogLevel.Trace); + + if (serilogLoggerProvider != null) + { + // Use a factory so that the container will dispose it + builder.Services.AddSingleton(_ => serilogLoggerProvider); + } + }); + + var serviceProvider = serviceCollection.BuildServiceProvider(); + var loggerFactory = serviceProvider.GetRequiredService(); + + var logger = loggerFactory.CreateLogger("GlobalTestLog"); + logger.LogInformation("Global Test Logging initialized at {logStart}. " + + "Configure the output directory via 'LoggingTestingFileLoggingDirectory' MSBuild property " + + "or set 'LoggingTestingDisableFileLogging' to 'true' to disable file logging.", + logStart.ToString("s")); + return new AssemblyTestLog(loggerFactory, logger, baseDirectory, assembly, serviceProvider); + } + + public static AssemblyTestLog ForAssembly(Assembly assembly) + { + lock (_lock) + { + if (!_logs.TryGetValue(assembly, out var log)) + { + var baseDirectory = TestFileOutputContext.GetOutputDirectory(assembly); + + log = Create(assembly, baseDirectory); + _logs[assembly] = log; + + // Try to clear previous logs, continue if it fails. + var assemblyBaseDirectory = TestFileOutputContext.GetAssemblyBaseDirectory(assembly); + if (!string.IsNullOrEmpty(assemblyBaseDirectory) && !TestFileOutputContext.GetPreserveExistingLogsInOutput(assembly)) + { + try + { + Directory.Delete(assemblyBaseDirectory, recursive: true); + } + catch { } + } + } + return log; + } + } + + private static TestFrameworkFileLoggerAttribute GetFileLoggerAttribute(Assembly assembly) + => assembly.GetCustomAttribute() + ?? throw new InvalidOperationException($"No {nameof(TestFrameworkFileLoggerAttribute)} found on the assembly {assembly.GetName().Name}. " + + "The attribute is added via msbuild properties of the Microsoft.Extensions.Logging.Testing. " + + "Please ensure the msbuild property is imported or a direct reference to Microsoft.Extensions.Logging.Testing is added."); + + private static SerilogLoggerProvider ConfigureFileLogging(string fileName, DateTimeOffset? logStart) + { + 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() + .Enrich.With(new AssemblyLogTimestampOffsetEnricher(logStart)) + .MinimumLevel.Verbose() + .WriteTo.File(fileName, outputTemplate: "[{TimestampOffset}] [{SourceContext}] [{Level}] {Message:l}{NewLine}{Exception}", flushToDiskInterval: TimeSpan.FromSeconds(1), shared: true) + .CreateLogger(); + return new SerilogLoggerProvider(serilogger, dispose: true); + } + + public void Dispose() + { + (_serviceProvider as IDisposable)?.Dispose(); + _globalLoggerFactory.Dispose(); + } + + private class AssemblyLogTimestampOffsetEnricher : ILogEventEnricher + { + private DateTimeOffset? _logStart; + + public AssemblyLogTimestampOffsetEnricher(DateTimeOffset? logStart) + { + _logStart = logStart; + } + + public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) + => logEvent.AddPropertyIfAbsent( + propertyFactory.CreateProperty( + "TimestampOffset", + _logStart.HasValue + ? $"{(DateTimeOffset.UtcNow - _logStart.Value).TotalSeconds.ToString("N3")}s" + : DateTimeOffset.UtcNow.ToString("s"))); + } + + private class Disposable : IDisposable + { + private Action _action; + + public Disposable(Action action) + { + _action = action; + } + + public void Dispose() + { + _action(); + } + } + } +} diff --git a/src/Testing/src/CollectDumpAttribute.cs b/src/Testing/src/CollectDumpAttribute.cs new file mode 100644 index 0000000000..5f4a1eee59 --- /dev/null +++ b/src/Testing/src/CollectDumpAttribute.cs @@ -0,0 +1,40 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Diagnostics; +using System.IO; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Testing; + +namespace Microsoft.Extensions.Logging.Testing +{ + /// + /// Capture the memory dump upon test failure. + /// + /// + /// This currently only works in Windows environments + /// + [AttributeUsage(AttributeTargets.Method, AllowMultiple = false)] + public class CollectDumpAttribute : Attribute, ITestMethodLifecycle + { + public Task OnTestStartAsync(TestContext context, CancellationToken cancellationToken) + { + return Task.CompletedTask; + } + + public Task OnTestEndAsync(TestContext context, Exception exception, CancellationToken cancellationToken) + { + if (exception != null) + { + var path = Path.Combine(context.FileOutput.TestClassOutputDirectory, context.FileOutput.GetUniqueFileName(context.FileOutput.TestName, ".dmp")); + var process = Process.GetCurrentProcess(); + DumpCollector.Collect(process, path); + } + + return Task.CompletedTask; + } + } +} diff --git a/src/Testing/src/DumpCollector/DumpCollector.Windows.cs b/src/Testing/src/DumpCollector/DumpCollector.Windows.cs new file mode 100644 index 0000000000..20395208d7 --- /dev/null +++ b/src/Testing/src/DumpCollector/DumpCollector.Windows.cs @@ -0,0 +1,77 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Diagnostics; +using System.IO; +using System.Runtime.InteropServices; +using Microsoft.Win32.SafeHandles; + +namespace Microsoft.Extensions.Logging.Testing +{ + public static partial class DumpCollector + { + private static class Windows + { + internal static void Collect(Process process, string outputFile) + { + // Open the file for writing + using (var stream = new FileStream(outputFile, FileMode.Create, FileAccess.ReadWrite, FileShare.None)) + { + // Dump the process! + var exceptionInfo = new NativeMethods.MINIDUMP_EXCEPTION_INFORMATION(); + if (!NativeMethods.MiniDumpWriteDump(process.Handle, (uint)process.Id, stream.SafeFileHandle, NativeMethods.MINIDUMP_TYPE.MiniDumpWithFullMemory, ref exceptionInfo, IntPtr.Zero, IntPtr.Zero)) + { + var err = Marshal.GetHRForLastWin32Error(); + Marshal.ThrowExceptionForHR(err); + } + } + } + + private static class NativeMethods + { + [DllImport("Dbghelp.dll")] + public static extern bool MiniDumpWriteDump(IntPtr hProcess, uint ProcessId, SafeFileHandle hFile, MINIDUMP_TYPE DumpType, ref MINIDUMP_EXCEPTION_INFORMATION ExceptionParam, IntPtr UserStreamParam, IntPtr CallbackParam); + + [StructLayout(LayoutKind.Sequential, Pack = 4)] + public struct MINIDUMP_EXCEPTION_INFORMATION + { + public uint ThreadId; + public IntPtr ExceptionPointers; + public int ClientPointers; + } + + [Flags] + public enum MINIDUMP_TYPE : uint + { + MiniDumpNormal = 0, + MiniDumpWithDataSegs = 1 << 0, + MiniDumpWithFullMemory = 1 << 1, + MiniDumpWithHandleData = 1 << 2, + MiniDumpFilterMemory = 1 << 3, + MiniDumpScanMemory = 1 << 4, + MiniDumpWithUnloadedModules = 1 << 5, + MiniDumpWithIndirectlyReferencedMemory = 1 << 6, + MiniDumpFilterModulePaths = 1 << 7, + MiniDumpWithProcessThreadData = 1 << 8, + MiniDumpWithPrivateReadWriteMemory = 1 << 9, + MiniDumpWithoutOptionalData = 1 << 10, + MiniDumpWithFullMemoryInfo = 1 << 11, + MiniDumpWithThreadInfo = 1 << 12, + MiniDumpWithCodeSegs = 1 << 13, + MiniDumpWithoutAuxiliaryState = 1 << 14, + MiniDumpWithFullAuxiliaryState = 1 << 15, + MiniDumpWithPrivateWriteCopyMemory = 1 << 16, + MiniDumpIgnoreInaccessibleMemory = 1 << 17, + MiniDumpWithTokenInformation = 1 << 18, + MiniDumpWithModuleHeaders = 1 << 19, + MiniDumpFilterTriage = 1 << 20, + MiniDumpWithAvxXStateContext = 1 << 21, + MiniDumpWithIptTrace = 1 << 22, + MiniDumpValidTypeFlags = (-1) ^ ((~1) << 22) + } + } + } + } +} diff --git a/src/Testing/src/DumpCollector/DumpCollector.cs b/src/Testing/src/DumpCollector/DumpCollector.cs new file mode 100644 index 0000000000..d67e109b38 --- /dev/null +++ b/src/Testing/src/DumpCollector/DumpCollector.cs @@ -0,0 +1,21 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Diagnostics; +using System.Runtime.InteropServices; + +namespace Microsoft.Extensions.Logging.Testing +{ + public static partial class DumpCollector + { + public static void Collect(Process process, string fileName) + { + if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + Windows.Collect(process, fileName); + } + // No implementations yet for macOS and Linux + } + } +} diff --git a/src/Testing/src/LoggedTest/ILoggedTest.cs b/src/Testing/src/LoggedTest/ILoggedTest.cs new file mode 100644 index 0000000000..750f45cd91 --- /dev/null +++ b/src/Testing/src/LoggedTest/ILoggedTest.cs @@ -0,0 +1,25 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Reflection; +using Microsoft.AspNetCore.Testing; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing +{ + public interface ILoggedTest : IDisposable + { + ILogger Logger { get; } + + ILoggerFactory LoggerFactory { get; } + + ITestOutputHelper TestOutputHelper { get; } + + // For back compat + IDisposable StartLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, string testName); + + void Initialize(TestContext context, MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper); + } +} diff --git a/src/Testing/src/LoggedTest/LoggedTest.cs b/src/Testing/src/LoggedTest/LoggedTest.cs new file mode 100644 index 0000000000..169a94f59d --- /dev/null +++ b/src/Testing/src/LoggedTest/LoggedTest.cs @@ -0,0 +1,26 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Reflection; +using Microsoft.AspNetCore.Testing; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing +{ + public class LoggedTest : LoggedTestBase + { + // Obsolete but keeping for back compat + public LoggedTest(ITestOutputHelper output = null) : base (output) { } + + public ITestSink TestSink { get; set; } + + public override void Initialize(TestContext context, MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper) + { + base.Initialize(context, methodInfo, testMethodArguments, testOutputHelper); + + TestSink = new TestSink(); + LoggerFactory.AddProvider(new TestLoggerProvider(TestSink)); + } + } +} diff --git a/src/Testing/src/LoggedTest/LoggedTestBase.cs b/src/Testing/src/LoggedTest/LoggedTestBase.cs new file mode 100644 index 0000000000..16dde9676c --- /dev/null +++ b/src/Testing/src/LoggedTest/LoggedTestBase.cs @@ -0,0 +1,122 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Linq; +using System.Reflection; +using System.Runtime.CompilerServices; +using System.Runtime.ExceptionServices; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.DependencyInjection; +using Serilog; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing +{ + public class LoggedTestBase : ILoggedTest, ITestMethodLifecycle + { + private ExceptionDispatchInfo _initializationException; + + private IDisposable _testLog; + + // Obsolete but keeping for back compat + public LoggedTestBase(ITestOutputHelper output = null) + { + TestOutputHelper = output; + } + + protected TestContext Context { get; private set; } + + // Internal for testing + internal string ResolvedTestClassName { get; set; } + + public string ResolvedLogOutputDirectory { get; set; } + + public string ResolvedTestMethodName { get; set; } + + public ILogger Logger { get; set; } + + public ILoggerFactory LoggerFactory { get; set; } + + public ITestOutputHelper TestOutputHelper { get; set; } + + public void AddTestLogging(IServiceCollection services) => services.AddSingleton(LoggerFactory); + + // For back compat + public IDisposable StartLog(out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null) => StartLog(out loggerFactory, LogLevel.Debug, testName); + + // For back compat + public IDisposable StartLog(out ILoggerFactory loggerFactory, LogLevel minLogLevel, [CallerMemberName] string testName = null) + { + return AssemblyTestLog.ForAssembly(GetType().GetTypeInfo().Assembly).StartTestLog(TestOutputHelper, GetType().FullName, out loggerFactory, minLogLevel, testName); + } + + public virtual void Initialize(TestContext context, MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper) + { + try + { + TestOutputHelper = testOutputHelper; + + var classType = GetType(); + var logLevelAttribute = methodInfo.GetCustomAttribute() + ?? methodInfo.DeclaringType.GetCustomAttribute() + ?? methodInfo.DeclaringType.Assembly.GetCustomAttribute(); + + // internal for testing + ResolvedTestClassName = context.FileOutput.TestClassName; + + _testLog = AssemblyTestLog + .ForAssembly(classType.GetTypeInfo().Assembly) + .StartTestLog( + TestOutputHelper, + context.FileOutput.TestClassName, + out var loggerFactory, + logLevelAttribute?.LogLevel ?? LogLevel.Debug, + out var resolvedTestName, + out var logDirectory, + context.FileOutput.TestName); + + ResolvedLogOutputDirectory = logDirectory; + ResolvedTestMethodName = resolvedTestName; + + LoggerFactory = loggerFactory; + Logger = loggerFactory.CreateLogger(classType); + } + catch (Exception e) + { + _initializationException = ExceptionDispatchInfo.Capture(e); + } + } + + public virtual void Dispose() + { + if (_testLog == null) + { + // It seems like sometimes the MSBuild goop that adds the test framework can end up in a bad state and not actually add it + // Not sure yet why that happens but the exception isn't clear so I'm adding this error so we can detect it better. + // -anurse + throw new InvalidOperationException("LoggedTest base class was used but nothing initialized it! The test framework may not be enabled. Try cleaning your 'obj' directory."); + } + + _initializationException?.Throw(); + _testLog.Dispose(); + } + + Task ITestMethodLifecycle.OnTestStartAsync(TestContext context, CancellationToken cancellationToken) + { + + Context = context; + + Initialize(context, context.TestMethod, context.MethodArguments, context.Output); + return Task.CompletedTask; + } + + Task ITestMethodLifecycle.OnTestEndAsync(TestContext context, Exception exception, CancellationToken cancellationToken) + { + return Task.CompletedTask; + } + } +} diff --git a/src/Testing/src/TestFrameworkFileLoggerAttribute.cs b/src/Testing/src/TestFrameworkFileLoggerAttribute.cs new file mode 100644 index 0000000000..61fa9993e8 --- /dev/null +++ b/src/Testing/src/TestFrameworkFileLoggerAttribute.cs @@ -0,0 +1,18 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using Microsoft.AspNetCore.Testing; + +namespace Microsoft.Extensions.Logging.Testing +{ + [AttributeUsage(AttributeTargets.Assembly, AllowMultiple = false)] + public class TestFrameworkFileLoggerAttribute : TestOutputDirectoryAttribute + { + public TestFrameworkFileLoggerAttribute(string preserveExistingLogsInOutput, string tfm, string baseDirectory = null) + : base(preserveExistingLogsInOutput, tfm, baseDirectory) + { + } + } +} diff --git a/src/Testing/src/build/Microsoft.Extensions.Logging.Testing.props b/src/Testing/src/build/Microsoft.Extensions.Logging.Testing.props new file mode 100644 index 0000000000..167efb3f82 --- /dev/null +++ b/src/Testing/src/build/Microsoft.Extensions.Logging.Testing.props @@ -0,0 +1,30 @@ + + + + $(RepositoryRoot) + $(ASPNETCORE_TEST_LOG_DIR) + $(RepoRoot)artifacts\log\ + + + + + true + false + + + + + <_Parameter1>Microsoft.AspNetCore.Testing.AspNetTestFramework + <_Parameter2>Microsoft.AspNetCore.Testing + + + + <_Parameter1>$(PreserveExistingLogsInOutput) + <_Parameter2>$(TargetFramework) + <_Parameter3 Condition="'$(LoggingTestingDisableFileLogging)' != 'true'">$(LoggingTestingFileLoggingDirectory) + + + + diff --git a/src/Testing/test/AssemblyTestLogTests.cs b/src/Testing/test/AssemblyTestLogTests.cs new file mode 100644 index 0000000000..27a7cf83cf --- /dev/null +++ b/src/Testing/test/AssemblyTestLogTests.cs @@ -0,0 +1,221 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.IO; +using System.Linq; +using System.Reflection; +using System.Runtime.CompilerServices; +using System.Text.RegularExpressions; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Testing; +using Xunit; + +namespace Microsoft.Extensions.Logging.Testing.Tests +{ + public class AssemblyTestLogTests : LoggedTest + { + private static readonly Assembly ThisAssembly = typeof(AssemblyTestLogTests).GetTypeInfo().Assembly; + private static readonly string ThisAssemblyName = ThisAssembly.GetName().Name; + private static readonly string TFM = new DirectoryInfo(AppContext.BaseDirectory).Name; + + [Fact] + public void FunctionalLogs_LogsPreservedFromNonFlakyRun() + { + } + + [Fact] + [Flaky("http://example.com", FlakyOn.All)] + public void FunctionalLogs_LogsPreservedFromFlakyRun() + { + } + + [Fact] + public void ForAssembly_ReturnsSameInstanceForSameAssembly() + { + Assert.Same( + AssemblyTestLog.ForAssembly(ThisAssembly), + AssemblyTestLog.ForAssembly(ThisAssembly)); + } + + [Fact] + public void TestLogWritesToITestOutputHelper() + { + var output = new TestTestOutputHelper(); + var assemblyLog = AssemblyTestLog.Create(ThisAssemblyName, baseDirectory: null); + + using (assemblyLog.StartTestLog(output, "NonExistant.Test.Class", out var loggerFactory)) + { + var logger = loggerFactory.CreateLogger("TestLogger"); + logger.LogInformation("Information!"); + + // Trace is disabled by default + logger.LogTrace("Trace!"); + } + + var testLogContent = MakeConsistent(output.Output); + + Assert.Equal( +@"[OFFSET] TestLifetime Information: Starting test TestLogWritesToITestOutputHelper at TIMESTAMP +[OFFSET] TestLogger Information: Information! +[OFFSET] TestLifetime Information: Finished test TestLogWritesToITestOutputHelper in DURATION +", testLogContent, ignoreLineEndingDifferences: true); + } + + [Fact] + public Task TestLogEscapesIllegalFileNames() => + RunTestLogFunctionalTest((tempDir) => + { + var illegalTestName = "T:e/s//t"; + var escapedTestName = "T_e_s_t"; + using (var testAssemblyLog = AssemblyTestLog.Create(ThisAssemblyName, baseDirectory: tempDir)) + using (testAssemblyLog.StartTestLog(output: null, className: "FakeTestAssembly.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, resolvedTestName: out var resolvedTestname, out var _, testName: illegalTestName)) + { + Assert.Equal(escapedTestName, resolvedTestname); + } + }); + + [Fact] + public Task TestLogWritesToGlobalLogFile() => + RunTestLogFunctionalTest((tempDir) => + { + // Because this test writes to a file, it is a functional test and should be logged + // but it's also testing the test logging facility. So this is pretty meta ;) + var logger = LoggerFactory.CreateLogger("Test"); + + using (var testAssemblyLog = AssemblyTestLog.Create(ThisAssemblyName, tempDir)) + { + logger.LogInformation("Created test log in {baseDirectory}", tempDir); + + using (testAssemblyLog.StartTestLog(output: null, className: $"{ThisAssemblyName}.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, testName: "FakeTestName")) + { + var testLogger = testLoggerFactory.CreateLogger("TestLogger"); + testLogger.LogInformation("Information!"); + testLogger.LogTrace("Trace!"); + } + } + + logger.LogInformation("Finished test log in {baseDirectory}", tempDir); + + var globalLogPath = Path.Combine(tempDir, ThisAssemblyName, TFM, "global.log"); + var testLog = Path.Combine(tempDir, ThisAssemblyName, TFM, "FakeTestClass", "FakeTestName.log"); + + Assert.True(File.Exists(globalLogPath), $"Expected global log file {globalLogPath} to exist"); + Assert.True(File.Exists(testLog), $"Expected test log file {testLog} to exist"); + + var globalLogContent = MakeConsistent(File.ReadAllText(globalLogPath)); + var testLogContent = MakeConsistent(File.ReadAllText(testLog)); + + Assert.Equal( +@"[OFFSET] [GlobalTestLog] [Information] Global Test Logging initialized at TIMESTAMP. Configure the output directory via 'LoggingTestingFileLoggingDirectory' MSBuild property or set 'LoggingTestingDisableFileLogging' to 'true' to disable file logging. +[OFFSET] [GlobalTestLog] [Information] Starting test FakeTestName +[OFFSET] [GlobalTestLog] [Information] Finished test FakeTestName in DURATION +", globalLogContent, ignoreLineEndingDifferences: true); + Assert.Equal( +@"[OFFSET] [TestLifetime] [Information] Starting test FakeTestName at TIMESTAMP +[OFFSET] [TestLogger] [Information] Information! +[OFFSET] [TestLogger] [Verbose] Trace! +[OFFSET] [TestLifetime] [Information] Finished test FakeTestName in DURATION +", testLogContent, ignoreLineEndingDifferences: true); + }); + + [Fact] + public Task TestLogTruncatesTestNameToAvoidLongPaths() => + RunTestLogFunctionalTest((tempDir) => + { + var longTestName = new string('0', 50) + new string('1', 50) + new string('2', 50) + new string('3', 50) + new string('4', 50); + var logger = LoggerFactory.CreateLogger("Test"); + using (var testAssemblyLog = AssemblyTestLog.Create(ThisAssemblyName, tempDir)) + { + logger.LogInformation("Created test log in {baseDirectory}", tempDir); + + using (testAssemblyLog.StartTestLog(output: null, className: $"{ThisAssemblyName}.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, testName: longTestName)) + { + testLoggerFactory.CreateLogger("TestLogger").LogInformation("Information!"); + } + } + logger.LogInformation("Finished test log in {baseDirectory}", tempDir); + + var testLogFiles = new DirectoryInfo(Path.Combine(tempDir, ThisAssemblyName, TFM, "FakeTestClass")).EnumerateFiles(); + var testLog = Assert.Single(testLogFiles); + var testFileName = Path.GetFileNameWithoutExtension(testLog.Name); + + // The first half of the file comes from the beginning of the test name passed to the logger + Assert.Equal(longTestName.Substring(0, testFileName.Length / 2), testFileName.Substring(0, testFileName.Length / 2)); + // The last half of the file comes from the ending of the test name passed to the logger + Assert.Equal(longTestName.Substring(longTestName.Length - testFileName.Length / 2, testFileName.Length / 2), testFileName.Substring(testFileName.Length - testFileName.Length / 2, testFileName.Length / 2)); + }); + + [Fact] + public Task TestLogEnumerateFilenamesToAvoidCollisions() => + RunTestLogFunctionalTest((tempDir) => + { + var logger = LoggerFactory.CreateLogger("Test"); + using (var testAssemblyLog = AssemblyTestLog.Create(ThisAssemblyName, tempDir)) + { + logger.LogInformation("Created test log in {baseDirectory}", tempDir); + + for (var i = 0; i < 10; i++) + { + using (testAssemblyLog.StartTestLog(output: null, className: $"{ThisAssemblyName}.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, testName: "FakeTestName")) + { + testLoggerFactory.CreateLogger("TestLogger").LogInformation("Information!"); + } + } + } + logger.LogInformation("Finished test log in {baseDirectory}", tempDir); + + // The first log file exists + Assert.True(File.Exists(Path.Combine(tempDir, ThisAssemblyName, TFM, "FakeTestClass", "FakeTestName.log"))); + + // Subsequent files exist + for (var i = 0; i < 9; i++) + { + Assert.True(File.Exists(Path.Combine(tempDir, ThisAssemblyName, TFM, "FakeTestClass", $"FakeTestName.{i}.log"))); + } + }); + + private static readonly Regex TimestampRegex = new Regex(@"\d+-\d+-\d+T\d+:\d+:\d+"); + private static readonly Regex TimestampOffsetRegex = new Regex(@"\d+\.\d+s"); + private static readonly Regex DurationRegex = new Regex(@"[^ ]+s$"); + + private async Task RunTestLogFunctionalTest(Action action, [CallerMemberName] string testName = null) + { + var tempDir = Path.Combine(Path.GetTempPath(), $"TestLogging_{Guid.NewGuid().ToString("N")}"); + try + { + action(tempDir); + } + finally + { + if (Directory.Exists(tempDir)) + { + try + { + Directory.Delete(tempDir, recursive: true); + } + catch + { + await Task.Delay(100); + Directory.Delete(tempDir, recursive: true); + } + } + } + } + + private static string MakeConsistent(string input) + { + return string.Join(Environment.NewLine, input.Split(new[] { Environment.NewLine }, StringSplitOptions.None) + .Select(line => + { + var strippedPrefix = line.IndexOf("[") >= 0 ? line.Substring(line.IndexOf("[")) : line; + + var strippedDuration = DurationRegex.Replace(strippedPrefix, "DURATION"); + var strippedTimestamp = TimestampRegex.Replace(strippedDuration, "TIMESTAMP"); + var strippedTimestampOffset = TimestampOffsetRegex.Replace(strippedTimestamp, "OFFSET"); + return strippedTimestampOffset; + })); + } + } +} diff --git a/src/Testing/test/LoggedTestXunitTests.cs b/src/Testing/test/LoggedTestXunitTests.cs new file mode 100644 index 0000000000..61d7802508 --- /dev/null +++ b/src/Testing/test/LoggedTestXunitTests.cs @@ -0,0 +1,193 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Linq; +using System.Reflection; +using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.DependencyInjection; +using Xunit; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing.Tests +{ + [LogLevel(LogLevel.Debug)] + [ShortClassName] + public class LoggedTestXunitTests : TestLoggedTest + { + private readonly ITestOutputHelper _output; + + public LoggedTestXunitTests(ITestOutputHelper output) + { + _output = output; + } + + [Fact] + public void LoggedFactInitializesLoggedTestProperties() + { + Assert.NotNull(Logger); + Assert.NotNull(LoggerFactory); + Assert.NotNull(TestSink); + Assert.NotNull(TestOutputHelper); + } + + [Theory] + [InlineData("Hello world")] + public void LoggedTheoryInitializesLoggedTestProperties(string argument) + { + Assert.NotNull(Logger); + Assert.NotNull(LoggerFactory); + Assert.NotNull(TestSink); + Assert.NotNull(TestOutputHelper); + // Use the test argument + Assert.NotNull(argument); + } + + [ConditionalFact] + public void ConditionalLoggedFactGetsInitializedLoggerFactory() + { + Assert.NotNull(Logger); + Assert.NotNull(LoggerFactory); + Assert.NotNull(TestSink); + Assert.NotNull(TestOutputHelper); + } + + [ConditionalTheory] + [InlineData("Hello world")] + public void LoggedConditionalTheoryInitializesLoggedTestProperties(string argument) + { + Assert.NotNull(Logger); + Assert.NotNull(LoggerFactory); + Assert.NotNull(TestSink); + Assert.NotNull(TestOutputHelper); + // Use the test argument + Assert.NotNull(argument); + } + + [Fact] + [LogLevel(LogLevel.Information)] + public void LoggedFactFilteredByMethodLogLevel() + { + Logger.LogInformation("Information"); + Logger.LogDebug("Debug"); + + var message = Assert.Single(TestSink.Writes); + Assert.Equal(LogLevel.Information, message.LogLevel); + Assert.Equal("Information", message.Formatter(message.State, null)); + } + + [Fact] + public void LoggedFactFilteredByClassLogLevel() + { + Logger.LogDebug("Debug"); + Logger.LogTrace("Trace"); + + var message = Assert.Single(TestSink.Writes); + Assert.Equal(LogLevel.Debug, message.LogLevel); + Assert.Equal("Debug", message.Formatter(message.State, null)); + } + + [Theory] + [InlineData("Hello world")] + [LogLevel(LogLevel.Information)] + public void LoggedTheoryFilteredByLogLevel(string argument) + { + Logger.LogInformation("Information"); + Logger.LogDebug("Debug"); + + var message = Assert.Single(TestSink.Writes); + Assert.Equal(LogLevel.Information, message.LogLevel); + Assert.Equal("Information", message.Formatter(message.State, null)); + + // Use the test argument + Assert.NotNull(argument); + } + + [Fact] + public void AddTestLoggingUpdatedWhenLoggerFactoryIsSet() + { + var loggerFactory = new LoggerFactory(); + var serviceCollection = new ServiceCollection(); + + LoggerFactory = loggerFactory; + AddTestLogging(serviceCollection); + + Assert.Same(loggerFactory, serviceCollection.BuildServiceProvider().GetRequiredService()); + } + + [ConditionalTheory] + [EnvironmentVariableSkipCondition("ASPNETCORE_TEST_LOG_DIR", "")] // The test name is only generated when logging is enabled via the environment variable + [InlineData(null)] + public void LoggedTheoryNullArgumentsAreEscaped(string argument) + { + Assert.NotNull(LoggerFactory); + Assert.Equal($"{nameof(LoggedTheoryNullArgumentsAreEscaped)}_null", ResolvedTestMethodName); + // Use the test argument + Assert.Null(argument); + } + + [Fact] + public void AdditionalSetupInvoked() + { + Assert.True(SetupInvoked); + } + + [Fact] + public void MessageWrittenEventInvoked() + { + WriteContext context = null; + TestSink.MessageLogged += ctx => context = ctx; + Logger.LogInformation("Information"); + Assert.Equal(TestSink.Writes.Single(), context); + } + + [Fact] + public void ScopeStartedEventInvoked() + { + BeginScopeContext context = null; + TestSink.ScopeStarted += ctx => context = ctx; + using (Logger.BeginScope("Scope")) {} + Assert.Equal(TestSink.Scopes.Single(), context); + } + } + + public class LoggedTestXunitLogLevelTests : LoggedTest + { + [Fact] + public void LoggedFactFilteredByAssemblyLogLevel() + { + Logger.LogTrace("Trace"); + + var message = Assert.Single(TestSink.Writes); + Assert.Equal(LogLevel.Trace, message.LogLevel); + Assert.Equal("Trace", message.Formatter(message.State, null)); + } + } + + public class LoggedTestXunitInitializationTests : TestLoggedTest + { + [Fact] + public void ITestOutputHelperInitializedByDefault() + { + Assert.True(ITestOutputHelperIsInitialized); + } + } + + public class TestLoggedTest : LoggedTest + { + public bool SetupInvoked { get; private set; } = false; + public bool ITestOutputHelperIsInitialized { get; private set; } = false; + + public override void Initialize(TestContext context, MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper) + { + base.Initialize(context, methodInfo, testMethodArguments, testOutputHelper); + + try + { + TestOutputHelper.WriteLine("Test"); + ITestOutputHelperIsInitialized = true; + } catch { } + SetupInvoked = true; + } + } +} diff --git a/src/Testing/test/TestTestOutputHelper.cs b/src/Testing/test/TestTestOutputHelper.cs new file mode 100644 index 0000000000..5a5f6aa85f --- /dev/null +++ b/src/Testing/test/TestTestOutputHelper.cs @@ -0,0 +1,37 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Text; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing.Tests +{ + public class TestTestOutputHelper : ITestOutputHelper + { + private StringBuilder _output = new StringBuilder(); + + public bool Throw { get; set; } + + public string Output => _output.ToString(); + + public void WriteLine(string message) + { + if (Throw) + { + throw new Exception("Boom!"); + } + _output.AppendLine(message); + } + + public void WriteLine(string format, params object[] args) + { + if (Throw) + { + throw new Exception("Boom!"); + } + _output.AppendLine(string.Format(format, args)); + } + } +}