diff --git a/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/MSTest.Acceptance.IntegrationTests.csproj b/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/MSTest.Acceptance.IntegrationTests.csproj index b6a40d63f3..69783fd394 100644 --- a/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/MSTest.Acceptance.IntegrationTests.csproj +++ b/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/MSTest.Acceptance.IntegrationTests.csproj @@ -23,6 +23,7 @@ + diff --git a/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/RunnerTests.cs b/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/RunnerTests.cs index 79c0533d02..30a95b9e78 100644 --- a/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/RunnerTests.cs +++ b/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/RunnerTests.cs @@ -34,7 +34,7 @@ public async SystemTask EnableMSTestRunner_True_Will_Run_Standalone([AllTargetFr $"{verb} {generator.TargetAssetPath} -c {buildConfiguration} -r {RID}", cancellationToken: TestContext.CancellationToken); - Build binLog = Serialization.Read(compilationResult.BinlogPath); + Build binLog = BinlogReader.Read(compilationResult.BinlogPath!); Assert.AreNotEqual(0, binLog.FindChildrenRecursive() .Count(x => x.Title.Contains("ProjectCapability") && x.Children.Any(c => ((Item)c).Name == "TestingPlatformServer"))); @@ -123,7 +123,7 @@ public async SystemTask EnableMSTestRunner_False_Wont_Flow_TestingPlatformServer DotnetMuxerResult result = await DotnetCli.RunAsync($"{verb} {generator.TargetAssetPath} -c {buildConfiguration} -r {RID} ", cancellationToken: TestContext.CancellationToken); - Build binLog = Serialization.Read(result.BinlogPath); + Build binLog = BinlogReader.Read(result.BinlogPath!); Assert.DoesNotContain(x => x.Title.Contains("ProjectCapability") && x.Children.Any(c => ((Item)c).Name == "TestingPlatformServer"), binLog.FindChildrenRecursive()); } diff --git a/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/SdkTests.cs b/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/SdkTests.cs index 1d3d184403..01c99a952b 100644 --- a/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/SdkTests.cs +++ b/test/IntegrationTests/MSTest.Acceptance.IntegrationTests/SdkTests.cs @@ -412,7 +412,7 @@ public async Task SettingIsTestApplicationToFalseReducesAddedExtensionsAndMakesP compilationResult.AssertExitCodeIs(0); - SL.Build binLog = SL.Serialization.Read(compilationResult.BinlogPath); + SL.Build binLog = BinlogReader.Read(compilationResult.BinlogPath!); SL.Task cscTask = binLog.FindChildrenRecursive(task => task.Name == "Csc").Single(); SL.Item[] references = [.. cscTask.FindChildrenRecursive(p => p.Name == "References").Single().Children.OfType()]; diff --git a/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/Helpers/BinlogReader.cs b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/Helpers/BinlogReader.cs new file mode 100644 index 0000000000..9a5aa0a7fa --- /dev/null +++ b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/Helpers/BinlogReader.cs @@ -0,0 +1,88 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +using SL = Microsoft.Build.Logging.StructuredLogger; + +namespace Microsoft.Testing.Platform.Acceptance.IntegrationTests.Helpers; + +/// +/// Reads the MSBuild binary logs that the acceptance tests assert over. Always read binlogs through this helper, +/// never through Serialization.Read directly. +/// +/// +/// +/// Microsoft.Build.Logging.StructuredLogger.Serialization.Read is not safe to call concurrently in a cold +/// process. The first concurrent reads race on the library's lazy static initialization, and a read that loses the +/// race does not throw: it returns a Build whose only children are an [Error] reading +/// "Error when opening the log file." and a warning, with no build content underneath. Every assertion made over +/// that tree is wrong. Positive assertions fail for no product reason, and negative assertions such as +/// Assert.DoesNotContain pass vacuously, so the race erodes coverage as well as reddening builds. +/// +/// +/// Both acceptance suites parallelize at method level, so binlog reads do overlap. Taking a single process-wide +/// lock around the read removes the race. Reading twelve binlogs costs about 1.00s serialized against 0.74s +/// unserialized, which is nothing next to a suite that takes twenty minutes. +/// +/// +internal static class BinlogReader +{ + /// + /// The text the reader puts on the error node it substitutes for the tree when it cannot open a binlog. + /// + private const string OpenFailureErrorText = "Error when opening the log file."; + + private static readonly Lock ReadLock = new(); + + /// + /// Reads , serialized against every other read that goes through this helper. + /// + /// + /// The reader returned an unusable tree. Never returns a silently empty Build. + /// + public static SL.Build Read(string binlogPath) + { + SL.Build build; + lock (ReadLock) + { + build = SL.Serialization.Read(binlogPath); + } + + // The lock is what removes the race, so this check is not expected to fire. It is here so that a future + // version of the reader cannot quietly reintroduce an empty tree and turn every assertion over it into a + // meaningless result. There is no retry: a read that fails with the lock held fails for a reason reading + // the same file again will not change. + string? corruption = DescribeCorruption(build); + + return corruption is null + ? build + : throw new InvalidOperationException( + $"Could not read the binlog '{binlogPath}' ({DescribeFile(binlogPath)}). " + + $"{corruption} Asserting over the returned tree would be meaningless, so the read fails here instead."); + } + + private static string? DescribeCorruption(SL.Build build) + { + // Deliberately not keyed on build.Succeeded: several call sites read the binlog of a build that failed on + // purpose. These are the shapes that only a failed read produces. + SL.Error? openFailure = build.FindFirstChild(error => error.Text == OpenFailureErrorText); + + return openFailure is not null + ? $"The reader returned an empty tree carrying '{openFailure.Text}'." + : build.FindFirstDescendant() is null + ? "The tree holds no AddItem nodes at all, which no real build produces." + : null; + } + + private static string DescribeFile(string binlogPath) + { + try + { + FileInfo file = new(binlogPath); + return file.Exists ? $"{file.Length} bytes on disk" : "no such file on disk"; + } + catch (Exception ex) when (ex is IOException or UnauthorizedAccessException) + { + return $"size unavailable: {ex.Message}"; + } + } +} diff --git a/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuild.KnownExtensionRegistration.cs b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuild.KnownExtensionRegistration.cs index 7783ac1927..de8f95932d 100644 --- a/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuild.KnownExtensionRegistration.cs +++ b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuild.KnownExtensionRegistration.cs @@ -42,7 +42,7 @@ public async Task Microsoft_Testing_Platform_Extensions_ShouldBe_Correctly_Regis testHostResult.AssertOutputContains("--retry-failed-tests"); testHostResult.AssertOutputContains("--capture-video"); - SL.Build binLog = SL.Serialization.Read(binlogFile); + SL.Build binLog = BinlogReader.Read(binlogFile); SL.Target generateSelfRegisteredExtensions = binLog.FindChildrenRecursive().Single(t => t.Name == "_GenerateSelfRegisteredExtensions"); SL.Task testingPlatformSelfRegisteredExtensions = generateSelfRegisteredExtensions.FindChildrenRecursive().Single(t => t.Name == "TestingPlatformSelfRegisteredExtensions"); SL.Message generatedSource = testingPlatformSelfRegisteredExtensions.FindChildrenRecursive().Single(m => m.Text.Contains("SelfRegisteredExtensions source:")); @@ -80,7 +80,7 @@ public async Task TestingPlatformBuilderHook_With_Conflicting_Metadata_Fails_Bui result.AssertOutputContains("Duplicate 'TestingPlatformBuilderHook' item with Include 'CONFLICT-HOOK-ID' has conflicting metadata."); // Ensure no self-registered extensions source file was generated when validation failed. - SL.Build binLog = SL.Serialization.Read(result.BinlogPath!); + SL.Build binLog = BinlogReader.Read(result.BinlogPath!); SL.Target? generateSelfRegisteredExtensions = binLog.FindChildrenRecursive().SingleOrDefault(t => t.Name == "_GenerateSelfRegisteredExtensions"); Assert.IsNotNull(generateSelfRegisteredExtensions); SL.Task testingPlatformSelfRegisteredExtensions = generateSelfRegisteredExtensions.FindChildrenRecursive().Single(t => t.Name == "TestingPlatformSelfRegisteredExtensions"); diff --git a/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuildTests.GenerateEntryPoint.cs b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuildTests.GenerateEntryPoint.cs index 4f67257f84..742de3413b 100644 --- a/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuildTests.GenerateEntryPoint.cs +++ b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/MSBuildTests.GenerateEntryPoint.cs @@ -26,7 +26,7 @@ public async Task When_GenerateTestingPlatformEntryPoint_IsFalse_NoEntryPointInj $"{(verb == Verb.publish ? $"publish -f {tfm}" : "build")} -c {compilationMode} -r {RID} -p:GenerateTestingPlatformEntryPoint=False {testAsset.TargetAssetPath} -v:n", failIfReturnValueIsNotZero: false, cancellationToken: TestContext.CancellationToken); - SL.Build binLog = SL.Serialization.Read(compilationResult.BinlogPath!); + SL.Build binLog = BinlogReader.Read(compilationResult.BinlogPath!); IEnumerable generateTestingPlatformEntryPointTargets = binLog.FindChildrenRecursive().Where(t => t.Name == "_GenerateTestingPlatformEntryPoint"); @@ -124,7 +124,7 @@ public async Task GenerateVBApplicationHelperWithoutEntryPoint() DotnetMuxerResult buildResult = await DotnetCli.RunAsync( $"build -c {BuildConfiguration.Debug} -p:GenerateTestingPlatformEntryPoint=false -p:GenerateTestingPlatformApplicationHelper=true -p:OutputType=Library {testAsset.TargetAssetPath} -v:n", cancellationToken: TestContext.CancellationToken); - SL.Build binLog = SL.Serialization.Read(buildResult.BinlogPath!); + SL.Build binLog = BinlogReader.Read(buildResult.BinlogPath!); SL.Task entryPointTask = binLog.FindChildrenRecursive().Single(t => t.Name == "TestingPlatformEntryPointTask"); string generatedSource = entryPointTask.FindChildrenRecursive().Single(m => m.Text.Contains("Entrypoint source:")).Text; @@ -176,7 +176,7 @@ public async Task GeneratedSourcesAreRegeneratedWhenMSBuildTaskChanges() DotnetMuxerResult buildResult = await DotnetCli.RunAsync( $"build -c {BuildConfiguration.Debug} {testAsset.TargetAssetPath} -v:n -nr:false", cancellationToken: TestContext.CancellationToken); - SL.Build binLog = SL.Serialization.Read(buildResult.BinlogPath!); + SL.Build binLog = BinlogReader.Read(buildResult.BinlogPath!); string taskAssembly = binLog.FindChildrenRecursive() .Single(t => t.Name == "TestingPlatformEntryPointTask") .FromAssembly; @@ -191,7 +191,7 @@ public async Task GeneratedSourcesAreRegeneratedWhenMSBuildTaskChanges() buildResult = await DotnetCli.RunAsync( $"build -c {BuildConfiguration.Debug} {taskFolderProperty} {testAsset.TargetAssetPath} -v:n -nr:false", cancellationToken: TestContext.CancellationToken); - binLog = SL.Serialization.Read(buildResult.BinlogPath!); + binLog = BinlogReader.Read(buildResult.BinlogPath!); Assert.HasCount(1, binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformEntryPointTask")); Assert.HasCount(1, binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformSelfRegisteredExtensions")); @@ -204,7 +204,7 @@ public async Task GeneratedSourcesAreRegeneratedWhenMSBuildTaskChanges() buildResult = await DotnetCli.RunAsync( $"build -c {BuildConfiguration.Debug} {taskFolderProperty} {testAsset.TargetAssetPath} -v:n -nr:false", cancellationToken: TestContext.CancellationToken); - binLog = SL.Serialization.Read(buildResult.BinlogPath!); + binLog = BinlogReader.Read(buildResult.BinlogPath!); Assert.HasCount(1, binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformEntryPointTask")); Assert.HasCount(1, binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformSelfRegisteredExtensions")); @@ -212,7 +212,7 @@ public async Task GeneratedSourcesAreRegeneratedWhenMSBuildTaskChanges() buildResult = await DotnetCli.RunAsync( $"build -c {BuildConfiguration.Debug} {taskFolderProperty} {testAsset.TargetAssetPath} -v:n -nr:false", cancellationToken: TestContext.CancellationToken); - binLog = SL.Serialization.Read(buildResult.BinlogPath!); + binLog = BinlogReader.Read(buildResult.BinlogPath!); Assert.IsEmpty(binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformEntryPointTask")); Assert.IsEmpty(binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformSelfRegisteredExtensions")); @@ -233,7 +233,7 @@ await DotnetCli.RunAsync( buildResult = await DotnetCli.RunAsync( $"build -c {BuildConfiguration.Debug} {selfRegistrationOnlyProperties} {testAsset.TargetAssetPath} -v:n -nr:false", cancellationToken: TestContext.CancellationToken); - binLog = SL.Serialization.Read(buildResult.BinlogPath!); + binLog = BinlogReader.Read(buildResult.BinlogPath!); Assert.IsEmpty(binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformEntryPointTask")); Assert.HasCount(1, binLog.FindChildrenRecursive().Where(t => t.Name == "TestingPlatformSelfRegisteredExtensions")); @@ -258,7 +258,7 @@ private async Task GenerateAndVerifyLanguageSpecificEntryPointAsync(string asset using TestAsset testAsset = await TestAsset.GenerateAssetAsync(assetName, finalSourceCode); DotnetMuxerResult buildResult = await DotnetCli.RunAsync($"{(verb == Verb.publish ? $"publish -f {tfm}" : "build")} -c {compilationMode} -r {RID} {testAsset.TargetAssetPath} -v:n", cancellationToken: TestContext.CancellationToken); - SL.Build binLog = SL.Serialization.Read(buildResult.BinlogPath!); + SL.Build binLog = BinlogReader.Read(buildResult.BinlogPath!); SL.Target[] generateTestingPlatformEntryPointTargets = binLog.FindChildrenRecursive().Where(t => t.Name == "_GenerateTestingPlatformEntryPoint").ToArray(); Assert.HasCount(1, generateTestingPlatformEntryPointTargets, "Expected exactly one _GenerateTestingPlatformEntryPoint target"); SL.Task[] testingPlatformEntryPointTasks = generateTestingPlatformEntryPointTargets[0].FindChildrenRecursive().Where(t => t.Name == "TestingPlatformEntryPointTask").ToArray(); @@ -286,7 +286,7 @@ private async Task GenerateAndVerifyLanguageSpecificEntryPointAsync(string asset File.Delete(buildResult.BinlogPath!); buildResult = await DotnetCli.RunAsync($"{(verb == Verb.publish ? $"publish -f {tfm}" : "build")} -c {compilationMode} -r {RID} {testAsset.TargetAssetPath} -v:n", cancellationToken: TestContext.CancellationToken); - binLog = SL.Serialization.Read(buildResult.BinlogPath!); + binLog = BinlogReader.Read(buildResult.BinlogPath!); generateTestingPlatformEntryPointTargets = binLog.FindChildrenRecursive().Where(t => t.Name == "_GenerateTestingPlatformEntryPoint" && t.Children.Count > 0).ToArray(); Assert.HasCount(1, generateTestingPlatformEntryPointTargets, "Expected exactly one _GenerateTestingPlatformEntryPoint target with children on rebuild"); SL.Message[] skipMessages = generateTestingPlatformEntryPointTargets[0].FindChildrenRecursive().Where(m => m.Text.Contains("Skipping target \"_GenerateTestingPlatformEntryPoint\" because all output files are up-to-date with respect to the input files.", StringComparison.OrdinalIgnoreCase)).ToArray(); diff --git a/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/PackagedApp.MSBuildRegistration.cs b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/PackagedApp.MSBuildRegistration.cs index d03a63975d..580574b058 100644 --- a/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/PackagedApp.MSBuildRegistration.cs +++ b/test/IntegrationTests/Microsoft.Testing.Platform.Acceptance.IntegrationTests/PackagedApp.MSBuildRegistration.cs @@ -1,4 +1,4 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. +// Copyright (c) Microsoft Corporation. All rights reserved. // Licensed under the MIT license. See LICENSE file in the project root for full license information. using SL = Microsoft.Build.Logging.StructuredLogger; @@ -26,7 +26,7 @@ public async Task PackagedApp_TestingPlatformBuilderHook_IsRegistered_ViaBuildPr $"build -c {BuildConfiguration.Release} {testAsset.TargetAssetPath} -v:n", cancellationToken: TestContext.CancellationToken); - SL.Build binLog = SL.Serialization.Read(result.BinlogPath!); + SL.Build binLog = BinlogReader.Read(result.BinlogPath!); SL.Target generateSelfRegisteredExtensions = binLog.FindChildrenRecursive().Single(t => t.Name == "_GenerateSelfRegisteredExtensions"); SL.Task testingPlatformSelfRegisteredExtensions = generateSelfRegisteredExtensions.FindChildrenRecursive().Single(t => t.Name == "TestingPlatformSelfRegisteredExtensions"); SL.Message generatedSource = testingPlatformSelfRegisteredExtensions.FindChildrenRecursive().Single(m => m.Text.Contains("SelfRegisteredExtensions source:"));