diff --git a/src/Logging/Logging.AzureAppServices/src/AzureAppServicesDiagnosticsSettings.cs b/src/Logging/Logging.AzureAppServices/src/AzureAppServicesDiagnosticsSettings.cs index f48480c70f..f93538218f 100644 --- a/src/Logging/Logging.AzureAppServices/src/AzureAppServicesDiagnosticsSettings.cs +++ b/src/Logging/Logging.AzureAppServices/src/AzureAppServicesDiagnosticsSettings.cs @@ -8,6 +8,7 @@ namespace Microsoft.Extensions.Logging.AzureAppServices /// /// Settings for Azure diagnostics logging. /// + [Obsolete("This type is obsolete and will be removed in a future version. The recommended alternative is AzureBlobLoggerOptions.")] public class AzureAppServicesDiagnosticsSettings { private TimeSpan _blobCommitPeriod = TimeSpan.FromSeconds(5); diff --git a/src/Logging/Logging.AzureAppServices/src/AzureAppServicesLoggerFactoryExtensions.cs b/src/Logging/Logging.AzureAppServices/src/AzureAppServicesLoggerFactoryExtensions.cs index 7970133d38..a0e73027fb 100644 --- a/src/Logging/Logging.AzureAppServices/src/AzureAppServicesLoggerFactoryExtensions.cs +++ b/src/Logging/Logging.AzureAppServices/src/AzureAppServicesLoggerFactoryExtensions.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; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; @@ -94,6 +95,7 @@ namespace Microsoft.Extensions.Logging /// Adds an Azure Web Apps diagnostics logger. /// /// The extension method argument + [Obsolete("This method is obsolete and will be removed in a future version. The recommended alternative is AddAzureWebAppDiagnostics(this ILoggingBuilder builder).")] public static ILoggerFactory AddAzureWebAppDiagnostics(this ILoggerFactory factory) { return AddAzureWebAppDiagnostics(factory, new AzureAppServicesDiagnosticsSettings()); @@ -104,6 +106,7 @@ namespace Microsoft.Extensions.Logging /// /// The extension method argument /// The setting object to configure loggers. + [Obsolete("This method is obsolete and will be removed in a future version. The recommended alternative is AddAzureWebAppDiagnostics(this ILoggingBuilder builder).")] public static ILoggerFactory AddAzureWebAppDiagnostics(this ILoggerFactory factory, AzureAppServicesDiagnosticsSettings settings) { var context = WebAppContext.Default; diff --git a/src/Logging/Logging.AzureAppServices/src/AzureBlobLoggerOptions.cs b/src/Logging/Logging.AzureAppServices/src/AzureBlobLoggerOptions.cs index eb466f4bb9..2f1285f8ac 100644 --- a/src/Logging/Logging.AzureAppServices/src/AzureBlobLoggerOptions.cs +++ b/src/Logging/Logging.AzureAppServices/src/AzureBlobLoggerOptions.cs @@ -11,11 +11,6 @@ namespace Microsoft.Extensions.Logging.AzureAppServices /// public class AzureBlobLoggerOptions: BatchingLoggerOptions { - public AzureBlobLoggerOptions() - { - BatchSize = 32; - } - private string _blobName = "applicationLog.txt"; /// diff --git a/src/Logging/Logging.AzureAppServices/src/Internal/BatchingLoggerOptions.cs b/src/Logging/Logging.AzureAppServices/src/Internal/BatchingLoggerOptions.cs index ccdf75e561..fbbb5cfd08 100644 --- a/src/Logging/Logging.AzureAppServices/src/Internal/BatchingLoggerOptions.cs +++ b/src/Logging/Logging.AzureAppServices/src/Internal/BatchingLoggerOptions.cs @@ -7,8 +7,8 @@ namespace Microsoft.Extensions.Logging.AzureAppServices.Internal { public class BatchingLoggerOptions { - private int? _batchSize = 32; - private int? _backgroundQueueSize; + private int? _batchSize; + private int? _backgroundQueueSize = 1000; private TimeSpan _flushPeriod = TimeSpan.FromSeconds(1); /// @@ -30,7 +30,7 @@ namespace Microsoft.Extensions.Logging.AzureAppServices.Internal /// /// Gets or sets the maximum size of the background log message queue or null for no limit. /// After maximum queue size is reached log event sink would start blocking. - /// Defaults to null. + /// Defaults to 1000. /// public int? BackgroundQueueSize { @@ -48,6 +48,7 @@ namespace Microsoft.Extensions.Logging.AzureAppServices.Internal /// /// Gets or sets a maximum number of events to include in a single batch or null for no limit. /// + /// Defaults to null. public int? BatchSize { get { return _batchSize; } diff --git a/src/Logging/Logging.Testing/src/AssemblyTestLog.cs b/src/Logging/Logging.Testing/src/AssemblyTestLog.cs index 97a67b11fa..e84df52554 100644 --- a/src/Logging/Logging.Testing/src/AssemblyTestLog.cs +++ b/src/Logging/Logging.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/Logging/Logging.Testing/src/LoggedTest.cs b/src/Logging/Logging.Testing/src/LoggedTest.cs deleted file mode 100644 index 58fcc1fb3e..0000000000 --- a/src/Logging/Logging.Testing/src/LoggedTest.cs +++ /dev/null @@ -1,45 +0,0 @@ -// 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 System.Runtime.CompilerServices; -using Microsoft.Extensions.DependencyInjection; -using Xunit.Abstractions; - -namespace Microsoft.Extensions.Logging.Testing -{ - public abstract class LoggedTest - { - // Obsolete but keeping for back compat - public LoggedTest(ITestOutputHelper output = null) - { - TestOutputHelper = output; - } - - // Internal for testing - internal string ResolvedTestMethodName { get; set; } - - // Internal for testing - internal string ResolvedTestClassName { get; set; } - - public ILogger Logger { get; set; } - - public ILoggerFactory LoggerFactory { get; set; } - - public ITestOutputHelper TestOutputHelper { get; set; } - - public ITestSink TestSink { get; set; } - - public void AddTestLogging(IServiceCollection services) => services.AddSingleton(LoggerFactory); - - public IDisposable StartLog(out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null) => StartLog(out loggerFactory, LogLevel.Information, testName); - - 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 AdditionalSetup() { } - } -} diff --git a/src/Logging/Logging.Testing/src/LoggedTest/ILoggedTest.cs b/src/Logging/Logging.Testing/src/LoggedTest/ILoggedTest.cs new file mode 100644 index 0000000000..a563cbdaf9 --- /dev/null +++ b/src/Logging/Logging.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/Logging/Logging.Testing/src/LoggedTest/LoggedTest.cs b/src/Logging/Logging.Testing/src/LoggedTest/LoggedTest.cs new file mode 100644 index 0000000000..64a9adec06 --- /dev/null +++ b/src/Logging/Logging.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/Logging/Logging.Testing/src/LoggedTest/LoggedTestBase.cs b/src/Logging/Logging.Testing/src/LoggedTest/LoggedTestBase.cs new file mode 100644 index 0000000000..f714a632a4 --- /dev/null +++ b/src/Logging/Logging.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/Logging/Logging.Testing/src/RetryContext.cs b/src/Logging/Logging.Testing/src/RetryContext.cs new file mode 100644 index 0000000000..2a774cfd3e --- /dev/null +++ b/src/Logging/Logging.Testing/src/RetryContext.cs @@ -0,0 +1,18 @@ +// 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 +{ + public class RetryContext + { + internal int Limit { get; set; } + + internal object TestClassInstance { get; set; } + + internal string Reason { get; set; } + + internal int CurrentIteration { get; set; } + } +} \ No newline at end of file diff --git a/src/Logging/Logging.Testing/src/TestFrameworkFileLoggerAttribute.cs b/src/Logging/Logging.Testing/src/TestFrameworkFileLoggerAttribute.cs new file mode 100644 index 0000000000..32d8f30584 --- /dev/null +++ b/src/Logging/Logging.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/Logging/Logging.Testing/src/Xunit/LoggedConditionalTheoryDiscoverer.cs b/src/Logging/Logging.Testing/src/Xunit/LoggedConditionalTheoryDiscoverer.cs index da5685bbfc..d239b1147c 100644 --- a/src/Logging/Logging.Testing/src/Xunit/LoggedConditionalTheoryDiscoverer.cs +++ b/src/Logging/Logging.Testing/src/Xunit/LoggedConditionalTheoryDiscoverer.cs @@ -32,6 +32,20 @@ namespace Microsoft.Extensions.Logging.Testing object[] dataRow) { var skipReason = testMethod.EvaluateSkipConditions(); + if (skipReason == null && dataRow?.Length > 0) + { + var obj = dataRow[0]; + if (obj != null) + { + var type = obj.GetType(); + var property = type.GetProperty("Skip"); + if (property != null && property.PropertyType.Equals(typeof(string))) + { + skipReason = property.GetValue(obj) as string; + } + } + } + return skipReason != null ? base.CreateTestCasesForSkippedDataRow(discoveryOptions, testMethod, theoryAttribute, dataRow, skipReason) : base.CreateTestCasesForDataRow(discoveryOptions, testMethod, theoryAttribute, dataRow); diff --git a/src/Logging/Logging.Testing/src/Xunit/LoggedTestFrameworkDiscoverer.cs b/src/Logging/Logging.Testing/src/Xunit/LoggedTestFrameworkDiscoverer.cs index bc02355c87..4b1668ce95 100644 --- a/src/Logging/Logging.Testing/src/Xunit/LoggedTestFrameworkDiscoverer.cs +++ b/src/Logging/Logging.Testing/src/Xunit/LoggedTestFrameworkDiscoverer.cs @@ -37,7 +37,7 @@ namespace Microsoft.Extensions.Logging.Testing IMessageBus messageBus, ITestFrameworkDiscoveryOptions discoveryOptions) { - if (typeof(LoggedTest).IsAssignableFrom(testMethod.TestClass.Class.ToRuntimeType())) + if (typeof(ILoggedTest).IsAssignableFrom(testMethod.TestClass.Class.ToRuntimeType())) { var factAttributes = testMethod.Method.GetCustomAttributes(typeof(FactAttribute)); if (factAttributes.Count() > 1) diff --git a/src/Logging/Logging.Testing/src/Xunit/LoggedTestInvoker.cs b/src/Logging/Logging.Testing/src/Xunit/LoggedTestInvoker.cs index 09fe03c2b7..708db37105 100644 --- a/src/Logging/Logging.Testing/src/Xunit/LoggedTestInvoker.cs +++ b/src/Logging/Logging.Testing/src/Xunit/LoggedTestInvoker.cs @@ -6,7 +6,6 @@ using System.Collections.Generic; using System.Linq; using System.Reflection; using System.Threading; -using System.Threading.Tasks; using Xunit.Abstractions; using Xunit.Sdk; @@ -14,7 +13,8 @@ namespace Microsoft.Extensions.Logging.Testing { public class LoggedTestInvoker : XunitTestInvoker { - private TestOutputHelper _output; + private readonly ITestOutputHelper _output; + private readonly RetryContext _retryContext; public LoggedTestInvoker( ITest test, @@ -25,73 +25,40 @@ namespace Microsoft.Extensions.Logging.Testing object[] testMethodArguments, IReadOnlyList beforeAfterAttributes, ExceptionAggregator aggregator, - CancellationTokenSource cancellationTokenSource) + CancellationTokenSource cancellationTokenSource, + ITestOutputHelper output, + RetryContext retryContext) : base(test, messageBus, testClass, constructorArguments, testMethod, testMethodArguments, beforeAfterAttributes, aggregator, cancellationTokenSource) { - } - - protected override Task BeforeTestMethodInvokedAsync() - { - if (_output != null) - { - _output.Initialize(MessageBus, Test); - } - - return base.BeforeTestMethodInvokedAsync(); - } - - protected override async Task AfterTestMethodInvokedAsync() - { - await base.AfterTestMethodInvokedAsync(); - - if (_output != null) - { - _output.Uninitialize(); - } + _output = output; + _retryContext = retryContext; } protected override object CreateTestClass() { var testClass = base.CreateTestClass(); - if (testClass is LoggedTest loggedTestClass) + (testClass as ILoggedTest).Initialize( + TestMethod, + TestMethodArguments, + _output ?? ConstructorArguments.SingleOrDefault(a => typeof(ITestOutputHelper).IsAssignableFrom(a.GetType())) as ITestOutputHelper); + + if (testClass is LoggedTestBase loggedTestBase) { - var classType = loggedTestClass.GetType(); - var logLevelAttribute = TestMethod.GetCustomAttribute() as LogLevelAttribute; - var testName = TestMethodArguments.Aggregate(TestMethod.Name, (a, b) => $"{a}-{(b ?? "null")}"); + // Used for testing + loggedTestBase.RetryContext = _retryContext; - // Try resolving ITestOutputHelper from constructor arguments - loggedTestClass.TestOutputHelper = ConstructorArguments?.SingleOrDefault(a => typeof(ITestOutputHelper).IsAssignableFrom(a.GetType())) as ITestOutputHelper; - - var useShortClassName = TestMethod.DeclaringType.GetCustomAttribute() - ?? TestMethod.DeclaringType.Assembly.GetCustomAttribute(); - var resolvedClassName = useShortClassName == null ? classType.FullName : classType.Name; - // None resolved so create a new one and retain a reference to it for initialization/uninitialization - if (loggedTestClass.TestOutputHelper == null) + if (_retryContext != null) { - loggedTestClass.TestOutputHelper = _output = new TestOutputHelper(); + // Log retry attempt as warning + if (_retryContext.CurrentIteration > 0) + { + loggedTestBase.Logger.LogWarning($"{TestMethod.Name} failed and retry conditions are met, re-executing. The reason for failure is {_retryContext.Reason}."); + } + + // Save the test class instance for non-static predicates + _retryContext.TestClassInstance = testClass; } - - AssemblyTestLog - .ForAssembly(classType.GetTypeInfo().Assembly) - .StartTestLog( - loggedTestClass.TestOutputHelper, - resolvedClassName, - out var loggerFactory, - logLevelAttribute?.LogLevel ?? LogLevel.Trace, - out var resolvedTestName, - testName); - - // internal for testing - loggedTestClass.ResolvedTestMethodName = resolvedTestName; - loggedTestClass.ResolvedTestClassName = resolvedClassName; - - loggedTestClass.LoggerFactory = loggerFactory; - loggedTestClass.Logger = loggerFactory.CreateLogger(classType); - loggedTestClass.TestSink = new TestSink(); - loggerFactory.AddProvider(new TestLoggerProvider(loggedTestClass.TestSink)); - - loggedTestClass.AdditionalSetup(); } return testClass; diff --git a/src/Logging/Logging.Testing/src/Xunit/LoggedTestRunner.cs b/src/Logging/Logging.Testing/src/Xunit/LoggedTestRunner.cs index 07ad0978d2..909ea10a6b 100644 --- a/src/Logging/Logging.Testing/src/Xunit/LoggedTestRunner.cs +++ b/src/Logging/Logging.Testing/src/Xunit/LoggedTestRunner.cs @@ -3,9 +3,13 @@ using System; using System.Collections.Generic; +using System.Linq; using System.Reflection; +using System.Runtime.InteropServices; using System.Threading; using System.Threading.Tasks; +using Microsoft.AspNetCore.Testing.xunit; +using Microsoft.Extensions.Logging.Testing; using Xunit.Abstractions; using Xunit.Sdk; @@ -27,7 +31,100 @@ namespace Microsoft.Extensions.Logging.Testing { } + protected async override Task> InvokeTestAsync(ExceptionAggregator aggregator) + { + var testOutputHelper = ConstructorArguments.SingleOrDefault(a => typeof(TestOutputHelper).IsAssignableFrom(a.GetType())) as TestOutputHelper + ?? new TestOutputHelper(); + testOutputHelper.Initialize(MessageBus, Test); + + var executionTime = await InvokeTestMethodAsync(aggregator, testOutputHelper); + + var output = testOutputHelper.Output; + testOutputHelper.Uninitialize(); + + return Tuple.Create(executionTime, output); + } + protected override Task InvokeTestMethodAsync(ExceptionAggregator aggregator) - => new LoggedTestInvoker(Test, MessageBus, TestClass, ConstructorArguments, TestMethod, TestMethodArguments, BeforeAfterAttributes, aggregator, CancellationTokenSource).RunAsync(); + => InvokeTestMethodAsync(aggregator, null); + + private async Task InvokeTestMethodAsync(ExceptionAggregator aggregator, ITestOutputHelper output) + { + var retryAttribute = GetRetryAttribute(TestMethod); + if (!typeof(LoggedTestBase).IsAssignableFrom(TestClass) || retryAttribute == null) + { + return await new LoggedTestInvoker(Test, MessageBus, TestClass, ConstructorArguments, TestMethod, TestMethodArguments, BeforeAfterAttributes, aggregator, CancellationTokenSource, output, null).RunAsync(); + } + + var retryPredicateMethodName = retryAttribute.RetryPredicateName; + var retryPredicateMethod = TestClass.GetMethod(retryPredicateMethodName, + BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.Static, + null, + new Type[] { typeof(Exception) }, + null) + ?? throw new InvalidOperationException($"No valid static retry predicate method {retryPredicateMethodName} was found on the type {TestClass.FullName}."); + + if (retryPredicateMethod.ReturnType != typeof(bool)) + { + throw new InvalidOperationException($"Retry predicate method {retryPredicateMethodName} on {TestClass.FullName} does not return bool."); + } + + var retryContext = new RetryContext() + { + Limit = retryAttribute.RetryLimit, + Reason = retryAttribute.RetryReason, + }; + + var retryAggregator = new ExceptionAggregator(); + var loggedTestInvoker = new LoggedTestInvoker(Test, MessageBus, TestClass, ConstructorArguments, TestMethod, TestMethodArguments, BeforeAfterAttributes, retryAggregator, CancellationTokenSource, output, retryContext); + var totalTime = 0.0M; + + do + { + retryAggregator.Clear(); + totalTime += await loggedTestInvoker.RunAsync(); + retryContext.CurrentIteration++; + } + while (retryAggregator.HasExceptions + && retryContext.CurrentIteration < retryContext.Limit + && (retryPredicateMethod.IsStatic + ? (bool)retryPredicateMethod.Invoke(null, new object[] { retryAggregator.ToException() }) + : (bool)retryPredicateMethod.Invoke(retryContext.TestClassInstance, new object[] { retryAggregator.ToException() })) + ); + + aggregator.Aggregate(retryAggregator); + return totalTime; + } + + + private RetryTestAttribute GetRetryAttribute(MethodInfo methodInfo) + { + var os = RuntimeInformation.IsOSPlatform(OSPlatform.OSX) ? OperatingSystems.MacOSX + : RuntimeInformation.IsOSPlatform(OSPlatform.Windows) ? OperatingSystems.Windows + : OperatingSystems.Linux; + + var attributeCandidate = methodInfo.GetCustomAttribute(); + + if (attributeCandidate != null && (attributeCandidate.OperatingSystems & os) != 0) + { + return attributeCandidate; + } + + attributeCandidate = methodInfo.DeclaringType.GetCustomAttribute(); + + if (attributeCandidate != null && (attributeCandidate.OperatingSystems & os) != 0) + { + return attributeCandidate; + } + + attributeCandidate = methodInfo.DeclaringType.Assembly.GetCustomAttribute(); + + if (attributeCandidate != null && (attributeCandidate.OperatingSystems & os) != 0) + { + return attributeCandidate; + } + + return null; + } } } diff --git a/src/Logging/Logging.Testing/src/Xunit/RetryTestAttribute.cs b/src/Logging/Logging.Testing/src/Xunit/RetryTestAttribute.cs new file mode 100644 index 0000000000..e85f2c517e --- /dev/null +++ b/src/Logging/Logging.Testing/src/Xunit/RetryTestAttribute.cs @@ -0,0 +1,68 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +using System; +using System.ComponentModel; +using Microsoft.AspNetCore.Testing.xunit; + +namespace Microsoft.Extensions.Logging.Testing +{ + /// + /// WARNING: This attribute should only be used on well understood flaky test failures caused by external issues and should be removed once the underlying issues have been resolved. + /// This is not intended to be a long term solution to ensure passing of flaky tests but instead a method to improve test reliability without reducing coverage. + /// Issues should be filed to remove these attributes from affected tests as soon as the underlying issue is fixed. + /// + [EditorBrowsable(EditorBrowsableState.Never)] + [AttributeUsage(AttributeTargets.Method | AttributeTargets.Class, AllowMultiple = false)] + public class RetryTestAttribute : Attribute + { + /// + /// WARNING: This attribute should only be used on well understood flaky test failures caused by external issues and should be removed once the underlying issues have been resolved. + /// This is not intended to be a long term solution to ensure passing of flaky tests but instead a method to improve test reliability without reducing coverage. + /// Issues should be filed to remove these attributes from affected tests as soon as the underlying issue is fixed. + /// + /// The predicate of the format Func<Exception,bool> that is used to determine if the test should be retried + /// The reason for retrying the test + /// The number of retries to attempt before failing the test, for most purposes this this should be kept at 2 to avoid excessive retries. + public RetryTestAttribute(string retryPredicateName, string retryReason, int retryLimit = 2) + : this(retryPredicateName, retryReason, OperatingSystems.Linux | OperatingSystems.MacOSX | OperatingSystems.Windows, retryLimit) { } + + /// + /// WARNING: This attribute should only be used on well understood flaky test failures caused by external issuesand should be removed once the underlying issues have been resolved. + /// This is not intended to be a long term solution to ensure passing of flaky tests but instead a method to improve test reliability without reducing coverage. + /// Issues should be filed to remove these attributes from affected tests as soon as the underlying issue is fixed. + /// + /// The os(es) this retry should be attempted on. + /// The predicate of the format Func<Exception,bool> that is used to determine if the test should be retried + /// The reason for retrying the test + /// The number of retries to attempt before failing the test, for most purposes this this should be kept at 2 to avoid excessive retries. + public RetryTestAttribute(string retryPredicateName, string retryReason, OperatingSystems operatingSystems, int retryLimit = 2) + { + if (string.IsNullOrEmpty(retryPredicateName)) + { + throw new ArgumentNullException(nameof(RetryPredicateName), "A valid non-empty predicate method name must be provided."); + } + if (string.IsNullOrEmpty(retryReason)) + { + throw new ArgumentNullException(nameof(retryReason), "A valid non-empty reason for retrying the test must be provided."); + } + if (retryLimit < 1) + { + throw new ArgumentOutOfRangeException(nameof(retryLimit), retryLimit, "Retry count must be positive."); + } + + OperatingSystems = operatingSystems; + RetryPredicateName = retryPredicateName; + RetryReason = retryReason; + RetryLimit = retryLimit; + } + + public string RetryPredicateName { get; } + + public string RetryReason { get; } + + public int RetryLimit { get; } + + public OperatingSystems OperatingSystems { get; } + } +} diff --git a/src/Logging/Logging.Testing/src/XunitLoggerFactoryExtensions.cs b/src/Logging/Logging.Testing/src/XunitLoggerFactoryExtensions.cs index 498ef39c35..f646a68e58 100644 --- a/src/Logging/Logging.Testing/src/XunitLoggerFactoryExtensions.cs +++ b/src/Logging/Logging.Testing/src/XunitLoggerFactoryExtensions.cs @@ -22,6 +22,12 @@ namespace Microsoft.Extensions.Logging return builder; } + public static ILoggingBuilder AddXunit(this ILoggingBuilder builder, ITestOutputHelper output, LogLevel minLevel, DateTimeOffset? logStart) + { + builder.Services.AddSingleton(new XunitLoggerProvider(output, minLevel, logStart)); + return builder; + } + public static ILoggerFactory AddXunit(this ILoggerFactory loggerFactory, ITestOutputHelper output) { loggerFactory.AddProvider(new XunitLoggerProvider(output)); @@ -33,5 +39,11 @@ namespace Microsoft.Extensions.Logging loggerFactory.AddProvider(new XunitLoggerProvider(output, minLevel)); return loggerFactory; } + + public static ILoggerFactory AddXunit(this ILoggerFactory loggerFactory, ITestOutputHelper output, LogLevel minLevel, DateTimeOffset? logStart) + { + loggerFactory.AddProvider(new XunitLoggerProvider(output, minLevel, logStart)); + return loggerFactory; + } } } diff --git a/src/Logging/Logging.Testing/src/XunitLoggerProvider.cs b/src/Logging/Logging.Testing/src/XunitLoggerProvider.cs index 60ca147a30..8e28d6a19f 100644 --- a/src/Logging/Logging.Testing/src/XunitLoggerProvider.cs +++ b/src/Logging/Logging.Testing/src/XunitLoggerProvider.cs @@ -12,6 +12,7 @@ namespace Microsoft.Extensions.Logging.Testing { private readonly ITestOutputHelper _output; private readonly LogLevel _minLevel; + private readonly DateTimeOffset? _logStart; public XunitLoggerProvider(ITestOutputHelper output) : this(output, LogLevel.Trace) @@ -19,14 +20,20 @@ namespace Microsoft.Extensions.Logging.Testing } public XunitLoggerProvider(ITestOutputHelper output, LogLevel minLevel) + : this(output, minLevel, null) + { + } + + public XunitLoggerProvider(ITestOutputHelper output, LogLevel minLevel, DateTimeOffset? logStart) { _output = output; _minLevel = minLevel; + _logStart = logStart; } public ILogger CreateLogger(string categoryName) { - return new XunitLogger(_output, categoryName, _minLevel); + return new XunitLogger(_output, categoryName, _minLevel, _logStart); } public void Dispose() @@ -40,12 +47,14 @@ namespace Microsoft.Extensions.Logging.Testing private readonly string _category; private readonly LogLevel _minLogLevel; private readonly ITestOutputHelper _output; + private DateTimeOffset? _logStart; - public XunitLogger(ITestOutputHelper output, string category, LogLevel minLogLevel) + public XunitLogger(ITestOutputHelper output, string category, LogLevel minLogLevel, DateTimeOffset? logStart) { _minLogLevel = minLogLevel; _category = category; _output = output; + _logStart = logStart; } public void Log( @@ -59,7 +68,8 @@ namespace Microsoft.Extensions.Logging.Testing // Buffer the message into a single string in order to avoid shearing the message when running across multiple threads. var messageBuilder = new StringBuilder(); - var timestamp = DateTime.Now.ToString("s"); + var timestamp = _logStart.HasValue ? $"{(DateTimeOffset.UtcNow - _logStart.Value).TotalSeconds.ToString("N3")}s" : DateTimeOffset.UtcNow.ToString("s"); + var firstLinePrefix = $"| [{timestamp}] {_category} {logLevel}: "; var lines = formatter(state, exception).Split(NewLineChars, StringSplitOptions.RemoveEmptyEntries); messageBuilder.AppendLine(firstLinePrefix + lines.FirstOrDefault() ?? string.Empty); diff --git a/src/Logging/Logging.Testing/src/build/Microsoft.Extensions.Logging.Testing.props b/src/Logging/Logging.Testing/src/build/Microsoft.Extensions.Logging.Testing.props index f98e3e13b5..0d2585146c 100644 --- a/src/Logging/Logging.Testing/src/build/Microsoft.Extensions.Logging.Testing.props +++ b/src/Logging/Logging.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/Logging/Logging.Testing/test/AssemblyTestLogTests.cs b/src/Logging/Logging.Testing/test/AssemblyTestLogTests.cs index 0efadb4367..20f597defc 100644 --- a/src/Logging/Logging.Testing/test/AssemblyTestLogTests.cs +++ b/src/Logging/Logging.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/Logging/Logging.Testing/test/LoggedTestXunitRetryTests.cs b/src/Logging/Logging.Testing/test/LoggedTestXunitRetryTests.cs new file mode 100644 index 0000000000..1e49f45046 --- /dev/null +++ b/src/Logging/Logging.Testing/test/LoggedTestXunitRetryTests.cs @@ -0,0 +1,101 @@ +// 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 Microsoft.AspNetCore.Testing.xunit; +using Xunit; + +namespace Microsoft.Extensions.Logging.Testing.Tests +{ + [RetryTest(nameof(RetryAllPredicate), "sample reason")] + public class LoggedTestXunitRetryTests : LoggedTest + { + [Fact] + public void CompletesWithoutRetryOnSuccess() + { + Assert.Equal(2, RetryContext.Limit); + + // This assert would fail on the second run + Assert.Equal(0, RetryContext.CurrentIteration); + } + + [Fact] + public void RetriesUntilSuccess() + { + // This assert will fail the first time but pass on the second + Assert.Equal(1, RetryContext.CurrentIteration); + + // This assert will ensure a message is logged for retried tests. + Assert.Equal(1, TestSink.Writes.Count); + var loggedMessage = TestSink.Writes.ToArray()[0]; + Assert.Equal(LogLevel.Warning, loggedMessage.LogLevel); + Assert.Equal($"{nameof(RetriesUntilSuccess)} failed and retry conditions are met, re-executing. The reason for failure is sample reason.", loggedMessage.Message); + } + + [ConditionalFact] + [OSSkipCondition(OperatingSystems.Windows)] + [RetryTest(nameof(RetryAllPredicate), "sample reason", OperatingSystems.Windows, 3)] + public void RetryCountNotOverridenWhenOSDoesNotMatch() + { + Assert.Equal(2, RetryContext.Limit); + } + + [ConditionalFact] + [OSSkipCondition(OperatingSystems.Linux | OperatingSystems.MacOSX)] + [RetryTest(nameof(RetryAllPredicate), "sample reason", OperatingSystems.Windows, 3)] + public void RetryCountOverridenWhenOSMatches() + { + Assert.Equal(3, RetryContext.Limit); + } + + [Fact] + [RetryTest(nameof(RetryInvalidOperationExceptionPredicate), "sample reason")] + public void RetryIfPredicateIsTrue() + { + if (RetryContext.CurrentIteration == 0) + { + Logger.LogWarning("Throw on first iteration"); + throw new Exception(); + } + + // This assert will ensure a message is logged for retried tests. + Assert.Equal(1, TestSink.Writes.Count); + var loggedMessage = TestSink.Writes.ToArray()[0]; + Assert.Equal(LogLevel.Warning, loggedMessage.LogLevel); + Assert.Equal($"{nameof(RetryIfPredicateIsTrue)} failed and retry conditions are met, re-executing. The reason for failure is sample reason.", loggedMessage.Message); + } + + // Static predicates are valid + private static bool RetryAllPredicate(Exception e) + => true; + + // Instance predicates are valid + private bool RetryInvalidOperationExceptionPredicate(Exception e) + => TestSink.Writes.Any(m => m.Message.Contains("Throw on first iteration")); + } + + [RetryTest(nameof(RetryAllPredicate), "sample reason")] + public class LoggedTestXunitRetryConstructorTest : LoggedTest + { + private static int _constructorInvocationCount; + + public LoggedTestXunitRetryConstructorTest() + { + _constructorInvocationCount++; + } + + [Fact] + public void RetriesUntilSuccess() + { + // The constructor is invoked before the test method but the current iteration is updated after + Assert.Equal(_constructorInvocationCount, RetryContext.CurrentIteration + 1); + + // This assert will fail the first time but pass on the second + Assert.Equal(1, RetryContext.CurrentIteration); + } + + private static bool RetryAllPredicate(Exception e) + => true; + } +} diff --git a/src/Logging/Logging.Testing/test/LoggedTestXunitTests.cs b/src/Logging/Logging.Testing/test/LoggedTestXunitTests.cs index 31fd6d631f..d1d8581193 100644 --- a/src/Logging/Logging.Testing/test/LoggedTestXunitTests.cs +++ b/src/Logging/Logging.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; } }