// Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. using System; using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Linq; using System.Reflection; using System.Runtime.CompilerServices; using System.Text; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Serilog; using Serilog.Core; using Serilog.Events; using Serilog.Extensions.Logging; using Xunit.Abstractions; using ILogger = Microsoft.Extensions.Logging.ILogger; namespace Microsoft.AspNetCore.Testing { public class AssemblyTestLog : IDisposable { private static readonly string MaxPathLengthEnvironmentVariableName = "ASPNETCORE_TEST_LOG_MAXPATH"; private static readonly string LogFileExtension = ".log"; private static readonly int MaxPathLength = GetMaxPathLength(); private static readonly object _lock = new object(); private static readonly Dictionary _logs = new Dictionary(); private readonly ILoggerFactory _globalLoggerFactory; private readonly ILogger _globalLogger; private readonly string _baseDirectory; private readonly Assembly _assembly; private readonly IServiceProvider _serviceProvider; private static int GetMaxPathLength() { var maxPathString = Environment.GetEnvironmentVariable(MaxPathLengthEnvironmentVariableName); var defaultMaxPath = 245; return string.IsNullOrEmpty(maxPathString) ? defaultMaxPath : int.Parse(maxPathString); } private AssemblyTestLog(ILoggerFactory globalLoggerFactory, ILogger globalLogger, string baseDirectory, Assembly assembly, IServiceProvider serviceProvider) { _globalLoggerFactory = globalLoggerFactory; _globalLogger = globalLogger; _baseDirectory = baseDirectory; _assembly = assembly; _serviceProvider = serviceProvider; } public IDisposable StartTestLog(ITestOutputHelper output, string className, out ILoggerFactory loggerFactory, [CallerMemberName] string testName = null) => StartTestLog(output, className, out loggerFactory, LogLevel.Debug, testName); public IDisposable StartTestLog(ITestOutputHelper output, string className, out ILoggerFactory loggerFactory, LogLevel minLogLevel, [CallerMemberName] string testName = null) => StartTestLog(output, className, out loggerFactory, minLogLevel, out var _, out var _, testName); internal IDisposable StartTestLog(ITestOutputHelper output, string className, out ILoggerFactory loggerFactory, LogLevel minLogLevel, out string resolvedTestName, out string logOutputDirectory, [CallerMemberName] string testName = null) { var logStart = DateTimeOffset.UtcNow; var serviceProvider = CreateLoggerServices(output, className, minLogLevel, out resolvedTestName, out logOutputDirectory, testName, logStart); var factory = serviceProvider.GetRequiredService(); loggerFactory = factory; var logger = loggerFactory.CreateLogger("TestLifetime"); var stopwatch = Stopwatch.StartNew(); var scope = logger.BeginScope("Test: {testName}", testName); _globalLogger.LogInformation("Starting test {testName}", testName); logger.LogInformation("Starting test {testName} at {logStart}", testName, logStart.ToString("s")); return new Disposable(() => { stopwatch.Stop(); _globalLogger.LogInformation("Finished test {testName} in {duration}s", testName, stopwatch.Elapsed.TotalSeconds); logger.LogInformation("Finished test {testName} in {duration}s", testName, stopwatch.Elapsed.TotalSeconds); scope.Dispose(); factory.Dispose(); (serviceProvider as IDisposable)?.Dispose(); }); } public ILoggerFactory CreateLoggerFactory(ITestOutputHelper output, string className, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) => CreateLoggerFactory(output, className, LogLevel.Trace, testName, logStart); public ILoggerFactory CreateLoggerFactory(ITestOutputHelper output, string className, LogLevel minLogLevel, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) => CreateLoggerServices(output, className, minLogLevel, out var _, out var _, testName, logStart).GetRequiredService(); public IServiceProvider CreateLoggerServices(ITestOutputHelper output, string className, LogLevel minLogLevel, out string normalizedTestName, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) => CreateLoggerServices(output, className, minLogLevel, out normalizedTestName, out var _, testName, logStart); public IServiceProvider CreateLoggerServices(ITestOutputHelper output, string className, LogLevel minLogLevel, out string normalizedTestName, out string logOutputDirectory, [CallerMemberName] string testName = null, DateTimeOffset? logStart = null) { normalizedTestName = string.Empty; logOutputDirectory = string.Empty; var assemblyName = _assembly.GetName().Name; // Try to shorten the class name using the assembly name if (className.StartsWith(assemblyName + ".")) { className = className.Substring(assemblyName.Length + 1); } SerilogLoggerProvider serilogLoggerProvider = null; if (!string.IsNullOrEmpty(_baseDirectory)) { logOutputDirectory = Path.Combine(_baseDirectory, className); testName = TestFileOutputContext.RemoveIllegalFileChars(testName); if (logOutputDirectory.Length + testName.Length + LogFileExtension.Length >= MaxPathLength) { _globalLogger.LogWarning($"Test name {testName} is too long. Please shorten test name."); // Shorten the test name by removing the middle portion of the testname var testNameLength = MaxPathLength - logOutputDirectory.Length - LogFileExtension.Length; if (testNameLength <= 0) { throw new InvalidOperationException("Output file path could not be constructed due to max path length restrictions. Please shorten test assembly, class or method names."); } testName = testName.Substring(0, testNameLength / 2) + testName.Substring(testName.Length - testNameLength / 2, testNameLength / 2); _globalLogger.LogWarning($"To prevent long paths test name was shortened to {testName}."); } var testOutputFile = Path.Combine(logOutputDirectory, $"{testName}{LogFileExtension}"); if (File.Exists(testOutputFile)) { _globalLogger.LogWarning($"Output log file {testOutputFile} already exists. Please try to keep log file names unique."); for (var i = 0; i < 1000; i++) { testOutputFile = Path.Combine(logOutputDirectory, $"{testName}.{i}{LogFileExtension}"); if (!File.Exists(testOutputFile)) { _globalLogger.LogWarning($"To resolve log file collision, the enumerated file {testOutputFile} will be used."); testName = $"{testName}.{i}"; break; } } } normalizedTestName = testName; serilogLoggerProvider = ConfigureFileLogging(testOutputFile, logStart); } var serviceCollection = new ServiceCollection(); serviceCollection.AddLogging(builder => { builder.SetMinimumLevel(minLogLevel); if (output != null) { builder.AddXunit(output, minLogLevel, logStart); } if (serilogLoggerProvider != null) { // Use a factory so that the container will dispose it builder.Services.AddSingleton(_ => serilogLoggerProvider); } }); return serviceCollection.BuildServiceProvider(); } // For back compat public static AssemblyTestLog Create(string assemblyName, string baseDirectory) => Create(Assembly.Load(new AssemblyName(assemblyName)), baseDirectory); public static AssemblyTestLog Create(Assembly assembly, string baseDirectory) { var logStart = DateTimeOffset.UtcNow; SerilogLoggerProvider serilogLoggerProvider = null; if (!string.IsNullOrEmpty(baseDirectory)) { baseDirectory = TestFileOutputContext.GetAssemblyBaseDirectory(assembly, baseDirectory); var globalLogFileName = Path.Combine(baseDirectory, "global.log"); serilogLoggerProvider = ConfigureFileLogging(globalLogFileName, logStart); } var serviceCollection = new ServiceCollection(); serviceCollection.AddLogging(builder => { // Global logging, when it's written, is expected to be outputted. So set the log level to minimum. builder.SetMinimumLevel(LogLevel.Trace); if (serilogLoggerProvider != null) { // Use a factory so that the container will dispose it builder.Services.AddSingleton(_ => serilogLoggerProvider); } }); var serviceProvider = serviceCollection.BuildServiceProvider(); var loggerFactory = serviceProvider.GetRequiredService(); var logger = loggerFactory.CreateLogger("GlobalTestLog"); logger.LogInformation("Global Test Logging initialized at {logStart}. " + "Configure the output directory via 'LoggingTestingFileLoggingDirectory' MSBuild property " + "or set 'LoggingTestingDisableFileLogging' to 'true' to disable file logging.", logStart.ToString("s")); return new AssemblyTestLog(loggerFactory, logger, baseDirectory, assembly, serviceProvider); } public static AssemblyTestLog ForAssembly(Assembly assembly) { lock (_lock) { if (!_logs.TryGetValue(assembly, out var log)) { var baseDirectory = TestFileOutputContext.GetOutputDirectory(assembly); log = Create(assembly, baseDirectory); _logs[assembly] = log; // Try to clear previous logs, continue if it fails. var assemblyBaseDirectory = TestFileOutputContext.GetAssemblyBaseDirectory(assembly); if (!string.IsNullOrEmpty(assemblyBaseDirectory) && !TestFileOutputContext.GetPreserveExistingLogsInOutput(assembly)) { try { Directory.Delete(assemblyBaseDirectory, recursive: true); } catch { } } } return log; } } private static TestFrameworkFileLoggerAttribute GetFileLoggerAttribute(Assembly assembly) => assembly.GetCustomAttribute() ?? throw new InvalidOperationException($"No {nameof(TestFrameworkFileLoggerAttribute)} found on the assembly {assembly.GetName().Name}. " + "The attribute is added via msbuild properties of the Microsoft.Extensions.Logging.Testing. " + "Please ensure the msbuild property is imported or a direct reference to Microsoft.Extensions.Logging.Testing is added."); private static SerilogLoggerProvider ConfigureFileLogging(string fileName, DateTimeOffset? logStart) { var dir = Path.GetDirectoryName(fileName); if (!Directory.Exists(dir)) { Directory.CreateDirectory(dir); } if (File.Exists(fileName)) { File.Delete(fileName); } var serilogger = new LoggerConfiguration() .Enrich.FromLogContext() .Enrich.With(new AssemblyLogTimestampOffsetEnricher(logStart)) .MinimumLevel.Verbose() .WriteTo.File(fileName, outputTemplate: "[{TimestampOffset}] [{SourceContext}] [{Level}] {Message:l}{NewLine}{Exception}", flushToDiskInterval: TimeSpan.FromSeconds(1), shared: true) .CreateLogger(); return new SerilogLoggerProvider(serilogger, dispose: true); } public void Dispose() { (_serviceProvider as IDisposable)?.Dispose(); _globalLoggerFactory.Dispose(); } private class AssemblyLogTimestampOffsetEnricher : ILogEventEnricher { private DateTimeOffset? _logStart; public AssemblyLogTimestampOffsetEnricher(DateTimeOffset? logStart) { _logStart = logStart; } public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) => logEvent.AddPropertyIfAbsent( propertyFactory.CreateProperty( "TimestampOffset", _logStart.HasValue ? $"{(DateTimeOffset.UtcNow - _logStart.Value).TotalSeconds.ToString("N3")}s" : DateTimeOffset.UtcNow.ToString("s"))); } private class Disposable : IDisposable { private Action _action; public Disposable(Action action) { _action = action; } public void Dispose() { _action(); } } } }