[17.14] Avoid hang when similar build requests are serviced (#12197)

Backports 370bb9d to 17.14.

### Summary

The MSBuild scheduler could hang when two similar-but-not-identical
requests were received and serviced in short proximity. VS calling
patterns trigger this sometimes.

This change handles the problematic case and additionally provides
breadcrumbs in the memory dump that this situation occurred to improve
future diagnosability of related issues.

### Customer Impact

VS hang observed from telemetry; VS Perf team wants backport.

### Regression?

No

### Testing

Has been in main (.NET SDK 10 builds) and internal VS preview for ~1
month, with good telemetry from VS int preview.

### Risk

Low due to bake time in main/int preview.

---------

Co-authored-by: YuliiaKovalova <[email protected]>

Author: rainersigwald

eng/Versions.props

@@ -2,8 +2,7 @@
 <!-- Copyright (c) .NET Foundation and contributors. All rights reserved. Licensed under the MIT license. See License.txt in the project root for full license information. -->
 <Project>
   <PropertyGroup>
-    <VersionPrefix>17.14.17</VersionPrefix>
-    <DotNetFinalVersionKind>release</DotNetFinalVersionKind>
+    <VersionPrefix>17.14.18</VersionPrefix><DotNetFinalVersionKind>release</DotNetFinalVersionKind>
     <PackageValidationBaselineVersion>17.13.9</PackageValidationBaselineVersion>
     <AssemblyVersion>15.1.0.0</AssemblyVersion>
     <PreReleaseVersionLabel>servicing</PreReleaseVersionLabel>

src/Build.UnitTests/BackEnd/Scheduler_Tests.cs

@@ -19,13 +19,13 @@
 
 namespace Microsoft.Build.UnitTests.BackEnd
 {
+    using System.Linq;
+    using FluentAssertions;
     using Microsoft.Build.Unittest;
 
     /// <summary>
     /// Tests of the scheduler.
     /// </summary>
-    // Ignore: Causing issues with other tests
-    // NOTE: marked as "internal" to disable the entire test class, as was done for MSTest.
     public class Scheduler_Tests : IDisposable
     {
         /// <summary>
@@ -58,6 +58,11 @@ public class Scheduler_Tests : IDisposable
         /// </summary>
         private BuildParameters _parameters;
 
+        /// <summary>
+        /// Configuration ID.
+        /// </summary>
+        private const int DefaultConfigId = 99;
+
         /// <summary>
         /// Set up
         /// </summary>
@@ -71,8 +76,8 @@ public Scheduler_Tests()
             _host = new MockHost();
             _scheduler = new Scheduler();
             _scheduler.InitializeComponent(_host);
-            CreateConfiguration(99, "parent.proj");
-            _defaultParentRequest = CreateBuildRequest(99, 99, Array.Empty<string>(), null);
+            CreateConfiguration(DefaultConfigId, "parent.proj");
+            _defaultParentRequest = CreateBuildRequest(99, DefaultConfigId, Array.Empty<string>(), null);
 
             // Set up the scheduler with one node to start with.
             _scheduler.ReportNodesCreated(new NodeInfo[] { new NodeInfo(1, NodeProviderType.InProc) });
@@ -387,8 +392,8 @@ public void VerifyRequestOrderingDoesNotAffectNodeCreationCountWithInProcAndAnyR
             _parameters.ShutdownInProcNodeOnBuildFinish = true;
             _buildManager = new BuildManager();
 
-            CreateConfiguration(99, "parent.proj");
-            _defaultParentRequest = CreateBuildRequest(99, 99, Array.Empty<string>(), null);
+            CreateConfiguration(DefaultConfigId, "parent.proj");
+            _defaultParentRequest = CreateBuildRequest(99, DefaultConfigId, Array.Empty<string>(), null);
 
             CreateConfiguration(1, "foo.proj");
             BuildRequest request1 = CreateBuildRequest(1, 1, new string[] { "foo" }, NodeAffinity.Any, _defaultParentRequest);
@@ -579,8 +584,8 @@ public void VerifyNoOverCreationOfNodesWithBuildLoop()
             _parameters.ShutdownInProcNodeOnBuildFinish = true;
             _buildManager = new BuildManager();
 
-            CreateConfiguration(99, "parent.proj");
-            _defaultParentRequest = CreateBuildRequest(99, 99, Array.Empty<string>(), null);
+            CreateConfiguration(DefaultConfigId, "parent.proj");
+            _defaultParentRequest = CreateBuildRequest(99, DefaultConfigId, Array.Empty<string>(), null);
 
             CreateConfiguration(1, "foo.proj");
             BuildRequest request1 = CreateBuildRequest(1, 1, new string[] { "foo" }, NodeAffinity.OutOfProc, _defaultParentRequest);
@@ -769,12 +774,13 @@ private BuildResult CacheBuildResult(BuildRequest request, string target, WorkUn
         }
 
         /// <summary>
-        /// Creates a build result for a request
+        /// Creates a build result for a request.
         /// </summary>
         private BuildResult CreateBuildResult(BuildRequest request, string target, WorkUnitResult workUnitResult)
         {
             BuildResult result = new BuildResult(request);
             result.AddResultsForTarget(target, new TargetResult(Array.Empty<TaskItem>(), workUnitResult));
+
             return result;
         }
 
@@ -789,23 +795,30 @@ private BuildRequest CreateBuildRequest(int nodeRequestId, int configId)
         /// <summary>
         /// Creates a build request.
         /// </summary>
-        private BuildRequest CreateBuildRequest(int nodeRequestId, int configId, string[] targets)
+        private BuildRequest CreateBuildRequest(int nodeRequestId, int configId, string[] targets, BuildRequestDataFlags buildRequestDataFlags = BuildRequestDataFlags.None)
         {
-            return CreateBuildRequest(nodeRequestId, configId, targets, _defaultParentRequest);
+            return CreateBuildRequest(nodeRequestId, configId, targets, _defaultParentRequest, buildRequestDataFlags);
         }
 
         /// <summary>
         /// Creates a build request.
         /// </summary>
-        private BuildRequest CreateBuildRequest(int nodeRequestId, int configId, string[] targets, BuildRequest parentRequest)
+        private BuildRequest CreateBuildRequest(int nodeRequestId, int configId, string[] targets, BuildRequest parentRequest, BuildRequestDataFlags buildRequestDataFlags = BuildRequestDataFlags.None)
         {
-            return CreateBuildRequest(nodeRequestId, configId, targets, NodeAffinity.Any, parentRequest);
+            return CreateBuildRequest(nodeRequestId, configId, targets, NodeAffinity.Any, parentRequest, buildRequestDataFlags: buildRequestDataFlags);
         }
 
         /// <summary>
         /// Creates a build request.
         /// </summary>
-        private BuildRequest CreateBuildRequest(int nodeRequestId, int configId, string[] targets, NodeAffinity nodeAffinity, BuildRequest parentRequest, ProxyTargets proxyTargets = null)
+        private BuildRequest CreateBuildRequest(
+            int nodeRequestId,
+            int configId,
+            string[] targets,
+            NodeAffinity nodeAffinity,
+            BuildRequest parentRequest,
+            ProxyTargets proxyTargets = null,
+            BuildRequestDataFlags buildRequestDataFlags = BuildRequestDataFlags.None)
         {
             (targets == null ^ proxyTargets == null).ShouldBeTrue();
 
@@ -826,16 +839,19 @@ private BuildRequest CreateBuildRequest(int nodeRequestId, int configId, string[
                     targets,
                     hostServices,
                     BuildEventContext.Invalid,
-                    parentRequest);
+                    parentRequest,
+                    buildRequestDataFlags: buildRequestDataFlags);
             }
 
             parentRequest.ShouldBeNull();
+
             return new BuildRequest(
                 submissionId: 1,
                 nodeRequestId,
                 configId,
                 proxyTargets,
-                hostServices);
+                hostServices,
+                buildRequestDataFlags: buildRequestDataFlags);
         }
 
         private BuildRequest CreateProxyBuildRequest(int nodeRequestId, int configId, ProxyTargets proxyTargets, BuildRequest parentRequest)
@@ -849,6 +865,69 @@ private BuildRequest CreateProxyBuildRequest(int nodeRequestId, int configId, Pr
                 proxyTargets);
         }
 
+        /// <summary>
+        /// The test checks how scheduler handles the duplicated requests and cache MISS for this case.
+        /// It's expected to have the duplicated request rescheduled for the execution.
+        /// </summary>
+        [Fact]
+        public void ReportResultTest_NoCacheHitForDupes()
+        {
+            // Create a duplicate of the existing _defaultParentRequest, but with a different build request flag, so we can't get the result from the cache.
+            BuildRequest duplicateRequest = CreateBuildRequest(2, configId: DefaultConfigId, Array.Empty<string>(), parentRequest: null, BuildRequestDataFlags.ProvideSubsetOfStateAfterBuild);
+
+            // Schedule the duplicate request -> it goes to unscheduled request due to duplicated configId
+            _scheduler.ReportRequestBlocked(2, new BuildRequestBlocker(-1, Array.Empty<string>(), [duplicateRequest]));
+
+            // try to get a result for the parent request and see if we get a result for the duplicate request
+            var results = _scheduler.ReportResult(1, CreateBuildResult(_defaultParentRequest, "", BuildResultUtilities.GetSuccessResult()))
+                .ToList();
+
+            results.ShouldNotBeNull();
+            results.Count.ShouldBe(2);
+
+            // Completed _defaultParentRequest
+            results[0].BuildResult.ShouldNotBeNull();
+            results[0].BuildResult.BuildRequestDataFlags.ShouldBe(BuildRequestDataFlags.None);
+            results[0].Action.ShouldBe(ScheduleActionType.SubmissionComplete);
+
+            // The automatically scheduled duplicated request.
+            results[1].BuildResult.ShouldBeNull();
+            results[1].NodeId.Should().Be(1);
+            results[1].Action.ShouldBe(ScheduleActionType.Schedule);
+            results[1].BuildRequest.BuildRequestDataFlags.ShouldBe(BuildRequestDataFlags.ProvideSubsetOfStateAfterBuild);
+        }
+
+        /// <summary>
+        /// The test checks how scheduler handles the duplicated requests and cache HIT for this case.
+        /// It's expected to have an immediate result for the duplicated request.
+        /// </summary>
+        [Fact]
+        public void ReportResultTest_CacheHitForDupes()
+        {
+            // Create a duplicate of the existing _defaultParentRequest.
+            BuildRequest duplicateRequest = CreateBuildRequest(2, configId: DefaultConfigId, Array.Empty<string>(), parentRequest: null, BuildRequestDataFlags.None);
+
+            // Schedule the duplicate request -> it goes to unscheduled request due to duplicated configId
+            _scheduler.ReportRequestBlocked(1, new BuildRequestBlocker(-1, Array.Empty<string>(), [duplicateRequest]));
+
+            // try to get a result for the parent request and see if we get a result for the duplicate request.
+            var results = _scheduler.ReportResult(1, CreateBuildResult(duplicateRequest, "", BuildResultUtilities.GetSuccessResult()))
+                .ToList();
+
+            results.ShouldNotBeNull();
+            results.Count.ShouldBe(2);
+
+            // Completed _defaultParentRequest
+            results[0].BuildResult.ShouldNotBeNull();
+            results[0].BuildResult.BuildRequestDataFlags.ShouldBe(BuildRequestDataFlags.None);
+            results[0].Action.ShouldBe(ScheduleActionType.SubmissionComplete);
+
+            // We hit cache and completed the duplicate request.
+            results[1].BuildResult.ShouldNotBeNull();
+            results[1].BuildResult.BuildRequestDataFlags.ShouldBe(BuildRequestDataFlags.None);
+            results[1].Action.ShouldBe(ScheduleActionType.SubmissionComplete);
+        }
+
         /// <summary>
         /// Method that fakes the actions done by BuildManager.PerformSchedulingActions
         /// </summary>

src/Build/BackEnd/BuildManager/BuildManager.cs

@@ -2390,8 +2390,8 @@ private void HandleNewRequest(int node, BuildRequestBlocker blocker)
                 }
             }
 
-            IEnumerable<ScheduleResponse> response = _scheduler!.ReportRequestBlocked(node, blocker);
-            PerformSchedulingActions(response);
+            IEnumerable<ScheduleResponse> responses = _scheduler!.ReportRequestBlocked(node, blocker);
+            PerformSchedulingActions(responses);
         }
 
         /// <summary>

src/Build/BackEnd/Components/Scheduler/Scheduler.cs

@@ -174,6 +174,21 @@ internal bool ForceAffinityOutOfProc
 
         private int _loggedWarningsForProxyBuildsOnOutOfProcNodes = 0;
 
+        /// <summary>
+        /// If we hit the path that prevents from completing build submission this flag is set. 
+        /// </summary>
+#pragma warning disable IDE0052 // Remove unread private members because we need them for traceability only
+#pragma warning disable CS0414 // The field is assigned but its value is never used
+        private bool _hitNoLoggingCompleted;
+
+        /// <summary>
+        /// Information about the missed submission.
+        /// </summary>
+        private string _noLoggingCompletedSubmissionDetails;
+
+#pragma warning restore IDE0052 // Remove unread private members
+#pragma warning restore CS0414 // The field is assigned but its value is never used
+
         /// <summary>
         /// Constructor.
         /// </summary>
@@ -445,30 +460,40 @@ public IEnumerable<ScheduleResponse> ReportResult(int nodeId, BuildResult result
                         // There are other requests which we can satisfy based on this result, lets pull the result out of the cache
                         // and satisfy those requests.  Normally a skipped result would lead to the cache refusing to satisfy the
                         // request, because the correct response in that case would be to attempt to rebuild the target in case there
-                        // are state changes that would cause it to now excute.  At this point, however, we already know that the parent
+                        // are state changes that would cause it to now execute.  At this point, however, we already know that the parent
                         // request has completed, and we already know that this request has the same global request ID, which means that
                         // its configuration and set of targets are identical -- from MSBuild's perspective, it's the same.  So since
                         // we're not going to attempt to re-execute it, if there are skipped targets in the result, that's fine. We just
                         // need to know what the target results are so that we can log them.
                         ScheduleResponse response = TrySatisfyRequestFromCache(parentNode, unscheduledRequest.BuildRequest, skippedResultsDoNotCauseCacheMiss: true);
 
-                        // If we have a response we need to tell the loggers that we satisified that request from the cache.
+                        // If we have a response we need to tell the loggers that we satisfied that request from the cache.
                         if (response != null)
                         {
                             LogRequestHandledFromCache(unscheduledRequest.BuildRequest, response.BuildResult);
+
+                            // Mark the request as complete (and the parent is no longer blocked by this request.)
+                            unscheduledRequest.Complete(newResult);
+                            responses.Add(response);
                         }
                         else
                         {
-                            // Response may be null if the result was never added to the cache. This can happen if the result has
-                            // an exception in it. If that is the case, we should report the result directly so that the
-                            // build manager knows that it needs to shut down logging manually.
-                            response = GetResponseForResult(parentNode, unscheduledRequest.BuildRequest, newResult.Clone());
+                            // This is a critical error case where a result should be in the cache but isn't.
+                            // The result might be missing from the cache if:
+                            // 1. The result contained an exception that prevented it from being cached properly
+                            // 2. The result was for a skipped target that couldn't satisfy all dependencies
+
+                            // Now scheduler will handle this situation automatically - the unscheduled request remains
+                            // in the unscheduled queue (_schedulingData.UnscheduledRequests) and will be picked up
+                            // in the next ScheduleUnassignedRequests execution to be properly rebuilt.
+
+                            // IMPORTANT: In earlier versions, we would hit this code path and did not handle it properly,
+                            // which caused deadlocks/hangs in Visual Studio. Without completing the request's
+                            // logging lifecycle, VS would never receive the completion callback and would wait
+                            // indefinitely, freezing the UI.
+                            _hitNoLoggingCompleted = true;
+                            _noLoggingCompletedSubmissionDetails = $"SubmissionId: {unscheduledRequest.BuildRequest.SubmissionId}; BuildRequestDataFlags: {unscheduledRequest.BuildRequest.BuildRequestDataFlags}";
                         }
-
-                        responses.Add(response);
-
-                        // Mark the request as complete (and the parent is no longer blocked by this request.)
-                        unscheduledRequest.Complete(newResult);
                     }
                 }
             }