src/Testing/test/AssemblyTestLogTests.cs - main - githubmirror/aspnetcore

src/Testing/test/AssemblyTestLogTests.cs
403 строки16 KB
William Godbe
Rename Microsoft.Aspnetcore.Testing to Microsoft.AspNetCore.InternalTesting (#51713)
02 ноя 2023, 03:15
02 ноя 2023, 03:15fc8deca
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.IO;
using System.Linq;
using System.Text.RegularExpressions;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Testing.Tests;
using Xunit;

namespace Microsoft.AspNetCore.InternalTesting;

public class AssemblyTestLogTests : LoggedTest
{
    [Fact]
    public void FunctionalLogs_LogsPreservedFromNonQuarantinedTest()
    {
    }

    [Fact]
    // Keep this test in quarantine, it verifies that quarantined test logs are preserved
    [QuarantinedTest("No issue")]
    public void FunctionalLogs_LogsPreservedFromQuarantinedTest()
    {
    }

    [Fact]
    public void ForAssembly_ReturnsSameInstanceForSameAssembly()
    {
        Assert.Same(
            AssemblyTestLog.ForAssembly(TestableAssembly.ThisAssembly),
            AssemblyTestLog.ForAssembly(TestableAssembly.ThisAssembly));
    }

    [Fact]
    public Task ForAssemblyWritesToAssemblyBaseDirectory() =>
        RunTestLogFunctionalTest((tempDir) =>
        {
            var logger = LoggerFactory.CreateLogger("Test");

            var assembly = TestableAssembly.Create(typeof(AssemblyTestLog), logDirectory: tempDir);
            var assemblyName = assembly.GetName().Name;
            var testName = $"{TestableAssembly.TestClassName}.{TestableAssembly.TestMethodName}";

            var tfmPath = Path.Combine(tempDir, assemblyName, TestableAssembly.TFM);
            var globalLogPath = Path.Combine(tfmPath, "global.log");
            var testLog = Path.Combine(tfmPath, TestableAssembly.TestClassName, $"{testName}.log");

            using var testAssemblyLog = AssemblyTestLog.ForAssembly(assembly);
            testAssemblyLog.OnCI = true;
            logger.LogInformation("Created test log in {baseDirectory}", tempDir);

            using (testAssemblyLog.StartTestLog(
                output: null,
                className: $"{assemblyName}.{TestableAssembly.TestClassName}",
                loggerFactory: out var testLoggerFactory,
                minLogLevel: LogLevel.Trace,
                testName: testName))
            {
                var testLogger = testLoggerFactory.CreateLogger("TestLogger");
                testLogger.LogInformation("Information!");
                testLogger.LogTrace("Trace!");
            }

            Assert.True(File.Exists(globalLogPath), $"Expected global log file {globalLogPath} to exist.");
            Assert.True(File.Exists(testLog), $"Expected test log file {testLog} to exist.");

            logger.LogInformation("Finished test log in {baseDirectory}", tempDir);
        });

    [Fact]
    public void TestLogWritesToITestOutputHelper()
    {
        var output = new TestTestOutputHelper();

        using var assemblyLog = AssemblyTestLog.Create(TestableAssembly.ThisAssembly, baseDirectory: null);
        using (assemblyLog.StartTestLog(output, "NonExistant.Test.Class", out var loggerFactory))
        {
            var logger = loggerFactory.CreateLogger("TestLogger");
            logger.LogInformation("Information!");

            // Trace is disabled by default
            logger.LogTrace("Trace!");
        }

        var testLogContent = MakeConsistent(output.Output);

        Assert.Equal(
@"[OFFSET] TestLifetime Information: Starting test TestLogWritesToITestOutputHelper at TIMESTAMP
[OFFSET] TestLogger Information: Information!
[OFFSET] TestLifetime Information: Finished test TestLogWritesToITestOutputHelper in DURATION
", testLogContent, ignoreLineEndingDifferences: true);
    }

    [Fact]
    public Task TestLogEscapesIllegalFileNames() =>
        RunTestLogFunctionalTest((tempDir) =>
        {
            var illegalTestName = "T:e/s//t";
            var escapedTestName = "T_e_s_t";

            using var testAssemblyLog = AssemblyTestLog.Create(
                TestableAssembly.ThisAssembly,
                baseDirectory: tempDir);
            using var disposable = testAssemblyLog.StartTestLog(
                output: null,
                className: "FakeTestAssembly.FakeTestClass",
                loggerFactory: out var testLoggerFactory,
                minLogLevel: LogLevel.Trace,
                resolvedTestName: out var resolvedTestname,
                out var _,
                testName: illegalTestName);
            Assert.Equal(escapedTestName, resolvedTestname);
        });

    [Fact]
    public Task TestLogWritesToGlobalLogFile() =>
        RunTestLogFunctionalTest((tempDir) =>
        {
            // Because this test writes to a file, it is a functional test and should be logged
            // but it's also testing the test logging facility. So this is pretty meta ;)
            var logger = LoggerFactory.CreateLogger("Test");

            using (var testAssemblyLog = AssemblyTestLog.Create(
                TestableAssembly.ThisAssembly,
                baseDirectory: tempDir))
            {
                testAssemblyLog.OnCI = false;
                logger.LogInformation("Created test log in {baseDirectory}", tempDir);

                using (testAssemblyLog.StartTestLog(
                    output: null,
                    className: $"{TestableAssembly.ThisAssemblyName}.FakeTestClass",
                    loggerFactory: out var testLoggerFactory,
                    minLogLevel: LogLevel.Trace,
                    testName: "FakeTestName"))
                {
                    var testLogger = testLoggerFactory.CreateLogger("TestLogger");
                    testLogger.LogInformation("Information!");
                    testLogger.LogTrace("Trace!");
                }
            }

            logger.LogInformation("Finished test log in {baseDirectory}", tempDir);

            var globalLogPath = Path.Combine(
                tempDir,
                TestableAssembly.ThisAssemblyName,
                TestableAssembly.TFM,
                "global.log");
            var testLog = Path.Combine(
                tempDir,
                TestableAssembly.ThisAssemblyName,
                TestableAssembly.TFM,
                "FakeTestClass",
                "FakeTestName.log");

            Assert.True(File.Exists(globalLogPath), $"Expected global log file {globalLogPath} to exist");
            Assert.True(File.Exists(testLog), $"Expected test log file {testLog} to exist");

            var globalLogContent = MakeConsistent(File.ReadAllText(globalLogPath));
            var testLogContent = MakeConsistent(File.ReadAllText(testLog));

            Assert.Equal(
@"[OFFSET] [GlobalTestLog] [Information] Global Test Logging initialized at TIMESTAMP. Configure the output directory via 'LoggingTestingFileLoggingDirectory' MSBuild property or set 'LoggingTestingDisableFileLogging' to 'true' to disable file logging.
[OFFSET] [GlobalTestLog] [Information] Starting test FakeTestName
[OFFSET] [GlobalTestLog] [Information] Finished test FakeTestName in DURATION
", globalLogContent, ignoreLineEndingDifferences: true);
            Assert.Equal(
@"[OFFSET] [TestLifetime] [Information] Starting test FakeTestName at TIMESTAMP
[OFFSET] [TestLogger] [Information] Information!
[OFFSET] [TestLogger] [Verbose] Trace!
[OFFSET] [TestLifetime] [Information] Finished test FakeTestName in DURATION
", testLogContent, ignoreLineEndingDifferences: true);
        });

    [Fact]
    public Task TestLogCleansLogFiles_AfterSuccessfulRun() =>
        RunTestLogFunctionalTest((tempDir) =>
        {
            var logger = LoggerFactory.CreateLogger("Test");
            var globalLogPath = Path.Combine(
                tempDir,
                TestableAssembly.ThisAssemblyName,
                TestableAssembly.TFM,
                "global.log");
            var testLog = Path.Combine(
                tempDir,
                TestableAssembly.ThisAssemblyName,
                TestableAssembly.TFM,
                "FakeTestClass",
                "FakeTestName.log");

            using (var testAssemblyLog = AssemblyTestLog.Create(
                TestableAssembly.ThisAssembly,
                baseDirectory: tempDir))
            {
                testAssemblyLog.OnCI = true;
                logger.LogInformation("Created test log in {baseDirectory}", tempDir);

                using (testAssemblyLog.StartTestLog(
                    output: null,
                    className: $"{TestableAssembly.ThisAssemblyName}.FakeTestClass",
                    loggerFactory: out var testLoggerFactory,
                    minLogLevel: LogLevel.Trace,
                    testName: "FakeTestName"))
                {
                    var testLogger = testLoggerFactory.CreateLogger("TestLogger");
                    testLogger.LogInformation("Information!");
                    testLogger.LogTrace("Trace!");
                }

                Assert.True(File.Exists(globalLogPath), $"Expected global log file {globalLogPath} to exist.");
                Assert.True(File.Exists(testLog), $"Expected test log file {testLog} to exist.");
            }

            logger.LogInformation("Finished test log in {baseDirectory}", tempDir);

            Assert.True(!File.Exists(globalLogPath), $"Expected no global log file {globalLogPath} to exist.");
            Assert.True(!File.Exists(testLog), $"Expected no test log file {testLog} to exist.");
        });

    [Fact]
    public Task TestLogDoesNotCleanLogFiles_AfterFailedRun() =>
        RunTestLogFunctionalTest((tempDir) =>
        {
            var logger = LoggerFactory.CreateLogger("Test");
            var globalLogPath = Path.Combine(
                tempDir,
                TestableAssembly.ThisAssemblyName,
                TestableAssembly.TFM,
                "global.log");
            var testLog = Path.Combine(
                tempDir,
                TestableAssembly.ThisAssemblyName,
                TestableAssembly.TFM,
                "FakeTestClass",
                "FakeTestName.log");

            using (var testAssemblyLog = AssemblyTestLog.Create(
                TestableAssembly.ThisAssembly,
                baseDirectory: tempDir))
            {
                testAssemblyLog.OnCI = true;
                logger.LogInformation("Created test log in {baseDirectory}", tempDir);

                using (testAssemblyLog.StartTestLog(
                    output: null,
                    className: $"{TestableAssembly.ThisAssemblyName}.FakeTestClass",
                    loggerFactory: out var testLoggerFactory,
                    minLogLevel: LogLevel.Trace,
                    testName: "FakeTestName"))
                {
                    var testLogger = testLoggerFactory.CreateLogger("TestLogger");
                    testLogger.LogInformation("Information!");
                    testLogger.LogTrace("Trace!");
                }

                testAssemblyLog.ReportTestFailure();
            }

            logger.LogInformation("Finished test log in {baseDirectory}", tempDir);

            Assert.True(File.Exists(globalLogPath), $"Expected global log file {globalLogPath} to exist.");
            Assert.True(File.Exists(testLog), $"Expected test log file {testLog} to exist.");
        });

    [Fact]
    public Task TestLogTruncatesTestNameToAvoidLongPaths() =>
        RunTestLogFunctionalTest((tempDir) =>
        {
            var longTestName = new string('0', 50) + new string('1', 50) + new string('2', 50) +
                new string('3', 50) + new string('4', 50);
            var logger = LoggerFactory.CreateLogger("Test");
            using (var testAssemblyLog = AssemblyTestLog.Create(
                TestableAssembly.ThisAssembly,
                baseDirectory: tempDir))
            {
                testAssemblyLog.OnCI = false;
                logger.LogInformation("Created test log in {baseDirectory}", tempDir);

                using (testAssemblyLog.StartTestLog(
                    output: null,
                    className: $"{TestableAssembly.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, TestableAssembly.ThisAssemblyName, TestableAssembly.TFM, "FakeTestClass"))
                .EnumerateFiles();
            var testLog = Assert.Single(testLogFiles);
            var testFileName = Path.GetFileNameWithoutExtension(testLog.Name);

            // The first half of the file comes from the beginning of the test name passed to the logger
            Assert.Equal(
                longTestName.Substring(0, testFileName.Length / 2),
                testFileName.Substring(0, testFileName.Length / 2));

            // The last half of the file comes from the ending of the test name passed to the logger
            Assert.Equal(
                longTestName.Substring(longTestName.Length - testFileName.Length / 2, testFileName.Length / 2),
                testFileName.Substring(testFileName.Length - testFileName.Length / 2, testFileName.Length / 2));
        });

    [Fact]
    public Task TestLogEnumerateFilenamesToAvoidCollisions() =>
        RunTestLogFunctionalTest((tempDir) =>
        {
            var logger = LoggerFactory.CreateLogger("Test");
            using (var testAssemblyLog = AssemblyTestLog.Create(
                TestableAssembly.ThisAssembly,
                baseDirectory: tempDir))
            {
                testAssemblyLog.OnCI = false;
                logger.LogInformation("Created test log in {baseDirectory}", tempDir);

                for (var i = 0; i < 10; i++)
                {
                    using (testAssemblyLog.StartTestLog(
                        output: null,
                        className: $"{TestableAssembly.ThisAssemblyName}.FakeTestClass",
                        loggerFactory: out var testLoggerFactory,
                        minLogLevel: LogLevel.Trace,
                        testName: "FakeTestName"))
                    {
                        testLoggerFactory.CreateLogger("TestLogger").LogInformation("Information!");
                    }
                }
            }

            logger.LogInformation("Finished test log in {baseDirectory}", tempDir);

            // The first log file exists
            Assert.True(File.Exists(Path.Combine(
                tempDir,
                TestableAssembly.ThisAssemblyName,
                TestableAssembly.TFM,
                "FakeTestClass",
                "FakeTestName.log")));

            // Subsequent files exist
            for (var i = 0; i < 9; i++)
            {
                Assert.True(File.Exists(Path.Combine(
                    tempDir,
                    TestableAssembly.ThisAssemblyName,
                    TestableAssembly.TFM,
                    "FakeTestClass",
                    $"FakeTestName.{i}.log")));
            }
        });

    private static readonly Regex TimestampRegex = new(@"\d+-\d+-\d+T\d+:\d+:\d+");
    private static readonly Regex TimestampOffsetRegex = new(@"\d+\.\d+s");
    private static readonly Regex DurationRegex = new(@"[^ ]+s$");

    private static async Task RunTestLogFunctionalTest(Action<string> action)
    {
        var tempDir = Path.Combine(Path.GetTempPath(), $"TestLogging_{Guid.NewGuid():N}");
        try
        {
            action(tempDir);
        }
        finally
        {
            if (Directory.Exists(tempDir))
            {
                try
                {
                    Directory.Delete(tempDir, recursive: true);
                }
                catch
                {
                    await Task.Delay(100);
                    Directory.Delete(tempDir, recursive: true);
                }
            }
        }
    }

    private static string MakeConsistent(string input)
    {
        return string.Join(Environment.NewLine, input.Split(new[] { Environment.NewLine }, StringSplitOptions.None)
            .Select(line =>
            {
                var strippedPrefix = line.Contains('[') ? line.Substring(line.IndexOf('[')) : line;

                var strippedDuration = DurationRegex.Replace(strippedPrefix, "DURATION");
                var strippedTimestamp = TimestampRegex.Replace(strippedDuration, "TIMESTAMP");
                var strippedTimestampOffset = TimestampOffsetRegex.Replace(strippedTimestamp, "OFFSET");
                return strippedTimestampOffset;
            }));
    }
}