Read acceptance-test binlogs behind a lock

test/IntegrationTests/MSTest.Acceptance.IntegrationTests/MSTest.Acceptance.IntegrationTests.csproj

@@ -23,6 +23,7 @@
     <Compile Include="$(RepoRoot)test\IntegrationTests\Microsoft.Testing.Platform.Acceptance.IntegrationTests\Helpers\AcceptanceAssert.cs" Link="Helpers\AcceptanceAssert.cs" />
     <Compile Include="$(RepoRoot)test\IntegrationTests\Microsoft.Testing.Platform.Acceptance.IntegrationTests\Helpers\AcceptanceFixture.cs" Link="Helpers\AcceptanceFixture.cs" />
     <Compile Include="$(RepoRoot)test\IntegrationTests\Microsoft.Testing.Platform.Acceptance.IntegrationTests\Helpers\AcceptanceTestBase.cs" Link="Helpers\AcceptanceTestBase.cs" />
+    <Compile Include="$(RepoRoot)test\IntegrationTests\Microsoft.Testing.Platform.Acceptance.IntegrationTests\Helpers\BinlogReader.cs" Link="Helpers\BinlogReader.cs" />
     <Compile Include="$(RepoRoot)test\IntegrationTests\Microsoft.Testing.Platform.Acceptance.IntegrationTests\ServerMode\**\*.cs" Link="ServerMode\%(RecursiveDir)%(FileName)%(Extension)" />
     <Compile Include="$(RepoRoot)\test\Utilities\Microsoft.Testing.TestInfrastructure\RootFinder.cs" Link="Helpers\RootFinder.cs" />
   </ItemGroup>

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<AddItem>()
             .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<AddItem>());
     }
 

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<SL.Task>(task => task.Name == "Csc").Single();
         SL.Item[] references = [.. cscTask.FindChildrenRecursive<SL.Parameter>(p => p.Name == "References").Single().Children.OfType<SL.Item>()];
 

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;
+
+/// <summary>
+/// Reads the MSBuild binary logs that the acceptance tests assert over. Always read binlogs through this helper,
+/// never through <c>Serialization.Read</c> directly.
+/// </summary>
+/// <remarks>
+/// <para>
+/// <c>Microsoft.Build.Logging.StructuredLogger.Serialization.Read</c> 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 <c>Build</c> whose only children are an <c>[Error]</c> 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
+/// <c>Assert.DoesNotContain</c> pass vacuously, so the race erodes coverage as well as reddening builds.
+/// </para>
+/// <para>
+/// 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.
+/// </para>
+/// </remarks>
+internal static class BinlogReader
+{
+    /// <summary>
+    /// The text the reader puts on the error node it substitutes for the tree when it cannot open a binlog.
+    /// </summary>
+    private const string OpenFailureErrorText = "Error when opening the log file.";
+
+    private static readonly Lock ReadLock = new();
+
+    /// <summary>
+    /// Reads <paramref name="binlogPath"/>, serialized against every other read that goes through this helper.
+    /// </summary>
+    /// <exception cref="InvalidOperationException">
+    /// The reader returned an unusable tree. Never returns a silently empty <c>Build</c>.
+    /// </exception>
+    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<SL.Error>(error => error.Text == OpenFailureErrorText);
+
+        return openFailure is not null
+            ? $"The reader returned an empty tree carrying '{openFailure.Text}'."
+            : build.FindFirstDescendant<SL.AddItem>() 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}";
+        }
+    }
+}

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<SL.Target>().Single(t => t.Name == "_GenerateSelfRegisteredExtensions");
         SL.Task testingPlatformSelfRegisteredExtensions = generateSelfRegisteredExtensions.FindChildrenRecursive<SL.Task>().Single(t => t.Name == "TestingPlatformSelfRegisteredExtensions");
         SL.Message generatedSource = testingPlatformSelfRegisteredExtensions.FindChildrenRecursive<SL.Message>().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<SL.Target>().SingleOrDefault(t => t.Name == "_GenerateSelfRegisteredExtensions");
         Assert.IsNotNull(generateSelfRegisteredExtensions);
         SL.Task testingPlatformSelfRegisteredExtensions = generateSelfRegisteredExtensions.FindChildrenRecursive<SL.Task>().Single(t => t.Name == "TestingPlatformSelfRegisteredExtensions");

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<SL.Target> generateTestingPlatformEntryPointTargets = binLog.FindChildrenRecursive<SL.Target>().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<SL.Task>().Single(t => t.Name == "TestingPlatformEntryPointTask");
         string generatedSource = entryPointTask.FindChildrenRecursive<SL.Message>().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<SL.Task>()
             .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<SL.Task>().Where(t => t.Name == "TestingPlatformEntryPointTask"));
         Assert.HasCount(1, binLog.FindChildrenRecursive<SL.Task>().Where(t => t.Name == "TestingPlatformSelfRegisteredExtensions"));
@@ -204,15 +204,15 @@ 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<SL.Task>().Where(t => t.Name == "TestingPlatformEntryPointTask"));
         Assert.HasCount(1, binLog.FindChildrenRecursive<SL.Task>().Where(t => t.Name == "TestingPlatformSelfRegisteredExtensions"));
 
         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<SL.Task>().Where(t => t.Name == "TestingPlatformEntryPointTask"));
         Assert.IsEmpty(binLog.FindChildrenRecursive<SL.Task>().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<SL.Task>().Where(t => t.Name == "TestingPlatformEntryPointTask"));
         Assert.HasCount(1, binLog.FindChildrenRecursive<SL.Task>().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<SL.Target>().Where(t => t.Name == "_GenerateTestingPlatformEntryPoint").ToArray();
         Assert.HasCount(1, generateTestingPlatformEntryPointTargets, "Expected exactly one _GenerateTestingPlatformEntryPoint target");
         SL.Task[] testingPlatformEntryPointTasks = generateTestingPlatformEntryPointTargets[0].FindChildrenRecursive<SL.Task>().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<SL.Target>().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<SL.Message>().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();

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<SL.Target>().Single(t => t.Name == "_GenerateSelfRegisteredExtensions");
         SL.Task testingPlatformSelfRegisteredExtensions = generateSelfRegisteredExtensions.FindChildrenRecursive<SL.Task>().Single(t => t.Name == "TestingPlatformSelfRegisteredExtensions");
         SL.Message generatedSource = testingPlatformSelfRegisteredExtensions.FindChildrenRecursive<SL.Message>().Single(m => m.Text.Contains("SelfRegisteredExtensions source:"));