diff --git a/src/Testing/src/AssemblyTestLog.cs b/src/Testing/src/AssemblyTestLog.cs index 97a67b11fa..e84df52554 100644 --- a/src/Testing/src/AssemblyTestLog.cs +++ b/src/Testing/src/AssemblyTestLog.cs @@ -8,10 +8,11 @@ using System.IO; using System.Linq; using System.Reflection; using System.Runtime.CompilerServices; -using System.Runtime.InteropServices; using System.Text; using Microsoft.Extensions.DependencyInjection; using Serilog; +using Serilog.Core; +using Serilog.Events; using Serilog.Extensions.Logging; using Xunit.Abstractions; @@ -19,7 +20,6 @@ namespace Microsoft.Extensions.Logging.Testing { public class AssemblyTestLog : IDisposable { - public static readonly string OutputDirectoryEnvironmentVariableName = "ASPNETCORE_TEST_LOG_DIR"; private static readonly string MaxPathLengthEnvironmentVariableName = "ASPNETCORE_TEST_LOG_MAXPATH"; private static readonly string LogFileExtension = ".log"; private static readonly int MaxPathLength = GetMaxPathLength(); @@ -38,7 +38,7 @@ namespace Microsoft.Extensions.Logging.Testing private readonly ILoggerFactory _globalLoggerFactory; private readonly ILogger _globalLogger; private readonly string _baseDirectory; - private readonly string _assemblyName; + private readonly Assembly _assembly; private readonly IServiceProvider _serviceProvider; private static int GetMaxPathLength() @@ -48,12 +48,12 @@ namespace Microsoft.Extensions.Logging.Testing return string.IsNullOrEmpty(maxPathString) ? defaultMaxPath : int.Parse(maxPathString); } - private AssemblyTestLog(ILoggerFactory globalLoggerFactory, ILogger globalLogger, string baseDirectory, string assemblyName, IServiceProvider serviceProvider) + private AssemblyTestLog(ILoggerFactory globalLoggerFactory, ILogger globalLogger, string baseDirectory, Assembly assembly, IServiceProvider serviceProvider) { _globalLoggerFactory = globalLoggerFactory; _globalLogger = globalLogger; _baseDirectory = baseDirectory; - _assemblyName = assemblyName; + _assembly = assembly; _serviceProvider = serviceProvider; } @@ -61,11 +61,12 @@ namespace Microsoft.Extensions.Logging.Testing 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 _, testName); + 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, [CallerMemberName] string testName = null) + internal IDisposable StartTestLog(ITestOutputHelper output, string className, out ILoggerFactory loggerFactory, LogLevel minLogLevel, out string resolvedTestName, out string logOutputDirectory, [CallerMemberName] string testName = null) { - var serviceProvider = CreateLoggerServices(output, className, minLogLevel, out resolvedTestName, testName); + 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"); @@ -75,7 +76,7 @@ namespace Microsoft.Extensions.Logging.Testing var scope = logger.BeginScope("Test: {testName}", testName); _globalLogger.LogInformation("Starting test {testName}", testName); - logger.LogInformation("Starting test {testName}", testName); + logger.LogInformation("Starting test {testName} at {logStart}", testName, logStart.ToString("s")); return new Disposable(() => { @@ -88,36 +89,39 @@ namespace Microsoft.Extensions.Logging.Testing }); } - public ILoggerFactory CreateLoggerFactory(ITestOutputHelper output, string className, [CallerMemberName] string testName = null) => - CreateLoggerFactory(output, className, LogLevel.Trace, testName); + 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) - { - return CreateLoggerServices(output, className, minLogLevel, out var _, testName).GetRequiredService(); - } + 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) + 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 + ".")) + if (className.StartsWith(assemblyName + ".")) { - className = className.Substring(_assemblyName.Length + 1); + className = className.Substring(assemblyName.Length + 1); } SerilogLoggerProvider serilogLoggerProvider = null; if (!string.IsNullOrEmpty(_baseDirectory)) { - var testOutputDirectory = Path.Combine(GetAssemblyBaseDirectory(_assemblyName, _baseDirectory), className); + logOutputDirectory = Path.Combine(GetAssemblyBaseDirectory(_baseDirectory, _assembly), className); testName = RemoveIllegalFileChars(testName); - if (testOutputDirectory.Length + testName.Length + LogFileExtension.Length >= MaxPathLength) + 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 - testOutputDirectory.Length - LogFileExtension.Length; + var testNameLength = MaxPathLength - logOutputDirectory.Length - LogFileExtension.Length; if (testNameLength <= 0) { @@ -129,7 +133,7 @@ namespace Microsoft.Extensions.Logging.Testing _globalLogger.LogWarning($"To prevent long paths test name was shortened to {testName}."); } - var testOutputFile = Path.Combine(testOutputDirectory, $"{testName}{LogFileExtension}"); + var testOutputFile = Path.Combine(logOutputDirectory, $"{testName}{LogFileExtension}"); if (File.Exists(testOutputFile)) { @@ -137,7 +141,7 @@ namespace Microsoft.Extensions.Logging.Testing for (var i = 0; i < 1000; i++) { - testOutputFile = Path.Combine(testOutputDirectory, $"{testName}.{i}{LogFileExtension}"); + testOutputFile = Path.Combine(logOutputDirectory, $"{testName}.{i}{LogFileExtension}"); if (!File.Exists(testOutputFile)) { @@ -149,7 +153,7 @@ namespace Microsoft.Extensions.Logging.Testing } normalizedTestName = testName; - serilogLoggerProvider = ConfigureFileLogging(testOutputFile); + serilogLoggerProvider = ConfigureFileLogging(testOutputFile, logStart); } var serviceCollection = new ServiceCollection(); @@ -159,7 +163,7 @@ namespace Microsoft.Extensions.Logging.Testing if (output != null) { - builder.AddXunit(output, minLogLevel); + builder.AddXunit(output, minLogLevel, logStart); } if (serilogLoggerProvider != null) @@ -172,14 +176,19 @@ namespace Microsoft.Extensions.Logging.Testing 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; - var globalLogDirectory = GetAssemblyBaseDirectory(assemblyName, baseDirectory); + var globalLogDirectory = GetAssemblyBaseDirectory(baseDirectory, assembly); if (!string.IsNullOrEmpty(globalLogDirectory)) { var globalLogFileName = Path.Combine(globalLogDirectory, "global.log"); - serilogLoggerProvider = ConfigureFileLogging(globalLogFileName); + serilogLoggerProvider = ConfigureFileLogging(globalLogFileName, logStart); } var serviceCollection = new ServiceCollection(); @@ -200,8 +209,11 @@ namespace Microsoft.Extensions.Logging.Testing var loggerFactory = serviceProvider.GetRequiredService(); 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 new AssemblyTestLog(loggerFactory, logger, baseDirectory, assemblyName, serviceProvider); + 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) @@ -210,13 +222,13 @@ namespace Microsoft.Extensions.Logging.Testing { if (!_logs.TryGetValue(assembly, out var log)) { - var assemblyName = assembly.GetName().Name; - var baseDirectory = Environment.GetEnvironmentVariable(OutputDirectoryEnvironmentVariableName); - log = Create(assemblyName, baseDirectory); + var baseDirectory = GetFileLoggerAttribute(assembly).BaseDirectory; + + log = Create(assembly, baseDirectory); _logs[assembly] = log; // Try to clear previous logs - var assemblyBaseDirectory = GetAssemblyBaseDirectory(assemblyName, baseDirectory); + var assemblyBaseDirectory = GetAssemblyBaseDirectory(baseDirectory, assembly); if (Directory.Exists(assemblyBaseDirectory)) { try @@ -230,16 +242,18 @@ namespace Microsoft.Extensions.Logging.Testing } } - private static string GetAssemblyBaseDirectory(string assemblyName, string baseDirectory) - { - if (!string.IsNullOrEmpty(baseDirectory)) - { - return Path.Combine(baseDirectory, assemblyName, RuntimeInformation.FrameworkDescription.TrimStart('.')); - } - return string.Empty; - } + private static string GetAssemblyBaseDirectory(string baseDirectory, Assembly assembly) + => string.IsNullOrEmpty(baseDirectory) + ? string.Empty + : Path.Combine(baseDirectory, assembly.GetName().Name, GetFileLoggerAttribute(assembly).TFM); - private static SerilogLoggerProvider ConfigureFileLogging(string fileName) + 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)) @@ -254,8 +268,9 @@ namespace Microsoft.Extensions.Logging.Testing var serilogger = new LoggerConfiguration() .Enrich.FromLogContext() + .Enrich.With(new AssemblyLogTimestampOffsetEnricher(logStart)) .MinimumLevel.Verbose() - .WriteTo.File(fileName, outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{SourceContext}] [{Level}] {Message}{NewLine}{Exception}", flushToDiskInterval: TimeSpan.FromSeconds(1), shared: true) + .WriteTo.File(fileName, outputTemplate: "[{TimestampOffset}] [{SourceContext}] [{Level}] {Message:l}{NewLine}{Exception}", flushToDiskInterval: TimeSpan.FromSeconds(1), shared: true) .CreateLogger(); return new SerilogLoggerProvider(serilogger, dispose: true); } @@ -287,6 +302,24 @@ namespace Microsoft.Extensions.Logging.Testing _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; diff --git a/src/Testing/src/LoggedTest/ILoggedTest.cs b/src/Testing/src/LoggedTest/ILoggedTest.cs new file mode 100644 index 0000000000..a563cbdaf9 --- /dev/null +++ b/src/Testing/src/LoggedTest/ILoggedTest.cs @@ -0,0 +1,23 @@ +// 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.Reflection; +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(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..64a9adec06 --- /dev/null +++ b/src/Testing/src/LoggedTest/LoggedTest.cs @@ -0,0 +1,24 @@ +// 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.Reflection; +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(MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper) + { + base.Initialize(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..f714a632a4 --- /dev/null +++ b/src/Testing/src/LoggedTest/LoggedTestBase.cs @@ -0,0 +1,82 @@ +// 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.Linq; +using System.Reflection; +using System.Runtime.CompilerServices; +using Microsoft.Extensions.DependencyInjection; +using Xunit.Abstractions; + +namespace Microsoft.Extensions.Logging.Testing +{ + public class LoggedTestBase : ILoggedTest + { + private IDisposable _testLog; + + // Obsolete but keeping for back compat + public LoggedTestBase(ITestOutputHelper output = null) + { + TestOutputHelper = output; + } + + // Internal for testing + internal string ResolvedTestClassName { get; set; } + + internal RetryContext RetryContext { 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(MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper) + { + TestOutputHelper = testOutputHelper; + + var classType = GetType(); + var logLevelAttribute = methodInfo.GetCustomAttribute(); + var testName = testMethodArguments.Aggregate(methodInfo.Name, (a, b) => $"{a}-{(b ?? "null")}"); + + var useShortClassName = methodInfo.DeclaringType.GetCustomAttribute() + ?? methodInfo.DeclaringType.Assembly.GetCustomAttribute(); + // internal for testing + ResolvedTestClassName = useShortClassName == null ? classType.FullName : classType.Name; + + _testLog = AssemblyTestLog + .ForAssembly(classType.GetTypeInfo().Assembly) + .StartTestLog( + TestOutputHelper, + ResolvedTestClassName, + out var loggerFactory, + logLevelAttribute?.LogLevel ?? LogLevel.Debug, + out var resolvedTestName, + out var logOutputDirectory, + testName); + + ResolvedLogOutputDirectory = logOutputDirectory; + ResolvedTestMethodName = resolvedTestName; + + LoggerFactory = loggerFactory; + Logger = loggerFactory.CreateLogger(classType); + } + + public virtual void Dispose() => _testLog.Dispose(); + } +} diff --git a/src/Testing/src/TestFrameworkFileLoggerAttribute.cs b/src/Testing/src/TestFrameworkFileLoggerAttribute.cs new file mode 100644 index 0000000000..32d8f30584 --- /dev/null +++ b/src/Testing/src/TestFrameworkFileLoggerAttribute.cs @@ -0,0 +1,20 @@ +// 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; + +namespace Microsoft.Extensions.Logging.Testing +{ + [AttributeUsage(AttributeTargets.Assembly, AllowMultiple = false)] + public class TestFrameworkFileLoggerAttribute : Attribute + { + public TestFrameworkFileLoggerAttribute(string tfm, string baseDirectory = null) + { + TFM = tfm; + BaseDirectory = baseDirectory; + } + + public string TFM { get; } + public string BaseDirectory { get; } + } +} \ No newline at end of file diff --git a/src/Testing/src/build/Microsoft.Extensions.Logging.Testing.props b/src/Testing/src/build/Microsoft.Extensions.Logging.Testing.props index f98e3e13b5..0d2585146c 100644 --- a/src/Testing/src/build/Microsoft.Extensions.Logging.Testing.props +++ b/src/Testing/src/build/Microsoft.Extensions.Logging.Testing.props @@ -1,8 +1,23 @@  - - - <_Parameter1>Microsoft.Extensions.Logging.Testing.LoggedTestFramework - <_Parameter2>Microsoft.Extensions.Logging.Testing - - + + + $(ASPNETCORE_TEST_LOG_DIR) + $(RepositoryRoot)artifacts\logs\ + + + + + + <_Parameter1>Microsoft.Extensions.Logging.Testing.LoggedTestFramework + <_Parameter2>Microsoft.Extensions.Logging.Testing + + + + <_Parameter1>$(TargetFramework) + <_Parameter2 Condition="'$(LoggingTestingDisableFileLogging)' != 'true'">$(LoggingTestingFileLoggingDirectory) + + + \ No newline at end of file diff --git a/src/Testing/test/AssemblyTestLogTests.cs b/src/Testing/test/AssemblyTestLogTests.cs index 0efadb4367..20f597defc 100644 --- a/src/Testing/test/AssemblyTestLogTests.cs +++ b/src/Testing/test/AssemblyTestLogTests.cs @@ -6,7 +6,6 @@ using System.IO; using System.Linq; using System.Reflection; using System.Runtime.CompilerServices; -using System.Runtime.InteropServices; using System.Text.RegularExpressions; using System.Threading.Tasks; using Xunit; @@ -15,7 +14,9 @@ namespace Microsoft.Extensions.Logging.Testing.Tests { public class AssemblyTestLogTests : LoggedTest { - private static readonly Assembly ThisAssembly = typeof(AssemblyTestLog).GetTypeInfo().Assembly; + 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 FullClassNameUsedWhenShortClassNameAttributeNotSpecified() @@ -35,7 +36,7 @@ namespace Microsoft.Extensions.Logging.Testing.Tests public void TestLogWritesToITestOutputHelper() { var output = new TestTestOutputHelper(); - var assemblyLog = AssemblyTestLog.Create("NonExistant.Test.Assembly", baseDirectory: null); + var assemblyLog = AssemblyTestLog.Create(ThisAssemblyName, baseDirectory: null); using (assemblyLog.StartTestLog(output, "NonExistant.Test.Class", out var loggerFactory)) { @@ -46,20 +47,23 @@ namespace Microsoft.Extensions.Logging.Testing.Tests logger.LogTrace("Trace!"); } - Assert.Equal(@"[TIMESTAMP] TestLifetime Information: Starting test TestLogWritesToITestOutputHelper -[TIMESTAMP] TestLogger Information: Information! -[TIMESTAMP] TestLifetime Information: Finished test TestLogWritesToITestOutputHelper in DURATION -", MakeConsistent(output.Output), ignoreLineEndingDifferences: true); + 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] private Task TestLogEscapesIllegalFileNames() => RunTestLogFunctionalTest((tempDir) => { - var illegalTestName = "Testing-https://localhost:5000"; - var escapedTestName = "Testing-https_localhost_5000"; - using (var testAssemblyLog = AssemblyTestLog.Create("FakeTestAssembly", baseDirectory: tempDir)) - using (testAssemblyLog.StartTestLog(output: null, className: "FakeTestAssembly.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, resolvedTestName: out var resolvedTestname, testName: illegalTestName)) + 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); } @@ -73,11 +77,11 @@ namespace Microsoft.Extensions.Logging.Testing.Tests // but it's also testing the test logging facility. So this is pretty meta ;) var logger = LoggerFactory.CreateLogger("Test"); - using (var testAssemblyLog = AssemblyTestLog.Create("FakeTestAssembly", tempDir)) + using (var testAssemblyLog = AssemblyTestLog.Create(ThisAssemblyName, tempDir)) { logger.LogInformation("Created test log in {baseDirectory}", tempDir); - using (testAssemblyLog.StartTestLog(output: null, className: "FakeTestAssembly.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, testName: "FakeTestName")) + 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!"); @@ -87,8 +91,8 @@ namespace Microsoft.Extensions.Logging.Testing.Tests logger.LogInformation("Finished test log in {baseDirectory}", tempDir); - var globalLogPath = Path.Combine(tempDir, "FakeTestAssembly", RuntimeInformation.FrameworkDescription.TrimStart('.'), "global.log"); - var testLog = Path.Combine(tempDir, "FakeTestAssembly", RuntimeInformation.FrameworkDescription.TrimStart('.'), "FakeTestClass", $"FakeTestName.log"); + 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"); @@ -96,14 +100,16 @@ namespace Microsoft.Extensions.Logging.Testing.Tests var globalLogContent = MakeConsistent(File.ReadAllText(globalLogPath)); var testLogContent = MakeConsistent(File.ReadAllText(testLog)); - Assert.Equal(@"[GlobalTestLog] [Information] Global Test Logging initialized. Set the 'ASPNETCORE_TEST_LOG_DIR' Environment Variable in order to create log files on disk. -[GlobalTestLog] [Information] Starting test ""FakeTestName"" -[GlobalTestLog] [Information] Finished test ""FakeTestName"" in DURATION + 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(@"[TestLifetime] [Information] Starting test ""FakeTestName"" -[TestLogger] [Information] Information! -[TestLogger] [Verbose] Trace! -[TestLifetime] [Information] Finished test ""FakeTestName"" in DURATION + 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); }); @@ -113,18 +119,18 @@ namespace Microsoft.Extensions.Logging.Testing.Tests { 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("FakeTestAssembly", tempDir)) + using (var testAssemblyLog = AssemblyTestLog.Create(ThisAssemblyName, tempDir)) { logger.LogInformation("Created test log in {baseDirectory}", tempDir); - using (testAssemblyLog.StartTestLog(output: null, className: "FakeTestAssembly.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, testName: longTestName)) + 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, "FakeTestAssembly", RuntimeInformation.FrameworkDescription.TrimStart('.'), "FakeTestClass")).EnumerateFiles(); + var testLogFiles = new DirectoryInfo(Path.Combine(tempDir, ThisAssemblyName, TFM, "FakeTestClass")).EnumerateFiles(); var testLog = Assert.Single(testLogFiles); var testFileName = Path.GetFileNameWithoutExtension(testLog.Name); @@ -139,13 +145,13 @@ namespace Microsoft.Extensions.Logging.Testing.Tests RunTestLogFunctionalTest((tempDir) => { var logger = LoggerFactory.CreateLogger("Test"); - using (var testAssemblyLog = AssemblyTestLog.Create("FakeTestAssembly", tempDir)) + 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: "FakeTestAssembly.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, testName: "FakeTestName")) + using (testAssemblyLog.StartTestLog(output: null, className: $"{ThisAssemblyName}.FakeTestClass", loggerFactory: out var testLoggerFactory, minLogLevel: LogLevel.Trace, testName: "FakeTestName")) { testLoggerFactory.CreateLogger("TestLogger").LogInformation("Information!"); } @@ -154,16 +160,17 @@ namespace Microsoft.Extensions.Logging.Testing.Tests logger.LogInformation("Finished test log in {baseDirectory}", tempDir); // The first log file exists - Assert.True(File.Exists(Path.Combine(tempDir, "FakeTestAssembly", RuntimeInformation.FrameworkDescription.TrimStart('.'), "FakeTestClass", $"FakeTestName.log"))); + 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, "FakeTestAssembly", RuntimeInformation.FrameworkDescription.TrimStart('.'), "FakeTestClass", $"FakeTestName.{i}.log"))); + 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) @@ -197,10 +204,10 @@ namespace Microsoft.Extensions.Logging.Testing.Tests { var strippedPrefix = line.IndexOf("[") >= 0 ? line.Substring(line.IndexOf("[")) : line; - var strippedDuration = - DurationRegex.Replace(strippedPrefix, "DURATION"); + var strippedDuration = DurationRegex.Replace(strippedPrefix, "DURATION"); var strippedTimestamp = TimestampRegex.Replace(strippedDuration, "TIMESTAMP"); - return strippedTimestamp; + var strippedTimestampOffset = TimestampOffsetRegex.Replace(strippedTimestamp, "OFFSET"); + return strippedTimestampOffset; })); } } diff --git a/src/Testing/test/LoggedTestXunitTests.cs b/src/Testing/test/LoggedTestXunitTests.cs index 31fd6d631f..d1d8581193 100644 --- a/src/Testing/test/LoggedTestXunitTests.cs +++ b/src/Testing/test/LoggedTestXunitTests.cs @@ -1,6 +1,7 @@ // 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.Reflection; using Microsoft.AspNetCore.Testing.xunit; using Microsoft.Extensions.DependencyInjection; using Xunit; @@ -130,12 +131,29 @@ namespace Microsoft.Extensions.Logging.Testing.Tests } } + 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 AdditionalSetup() + public override void Initialize(MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper) { + base.Initialize(methodInfo, testMethodArguments, testOutputHelper); + + try + { + TestOutputHelper.WriteLine("Test"); + ITestOutputHelperIsInitialized = true; + } catch { } SetupInvoked = true; } }