Don't schedule proxy builds to inproc node if their configs previousl…

…y built on oop nodes (#6635)

Fixes a bug in proxy build scheduling introduced by #6386. If a the BuildRequestConfiguration associated with a proxy request has been built before on an out of proc (oop) node then the scheduler will fail with either one of:
- affinity mismatch error. This happens when the proxy build is assigned to the inproc (inp) node but its configuration is already assigned to an oop node `AND` serving other existing requests, either blocked or running.
- unscheduled requests remain even if there's free oop nodes that can serve them. This happens (as far as I can tell) when the proxy's configuration is already assigned to an oop node (because a previously built non proxy request was assigned there) `AND` there's no other existing requests for that configuration

The fix in this PR is to not assign a proxy build to the inproc node if its configuration was previously assigned to another node.

src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs

@@ -233,6 +233,30 @@ public enum ErrorKind
             LoggedError
         }
 
+        public class ConfigurableMockCache : ProjectCachePluginBase
+        {
+            public Func<BuildRequestData, PluginLoggerBase, CancellationToken, Task<CacheResult>>? GetCacheResultImplementation { get; set; }
+            public override Task BeginBuildAsync(CacheContext context, PluginLoggerBase logger, CancellationToken cancellationToken)
+            {
+                return Task.CompletedTask;
+            }
+
+            public override Task<CacheResult> GetCacheResultAsync(
+                BuildRequestData buildRequest,
+                PluginLoggerBase logger,
+                CancellationToken cancellationToken)
+            {
+                return GetCacheResultImplementation != null
+                    ? GetCacheResultImplementation(buildRequest, logger, cancellationToken)
+                    : Task.FromResult(CacheResult.IndicateNonCacheHit(CacheResultType.CacheNotApplicable));
+            }
+
+            public override Task EndBuildAsync(PluginLoggerBase logger, CancellationToken cancellationToken)
+            {
+                return Task.CompletedTask;
+            }
+        }
+
         public class InstanceMockCache : ProjectCachePluginBase
         {
             private readonly GraphCacheResponse? _testData;
@@ -1475,6 +1499,97 @@ public void ParallelStressTest(bool useSynchronousLogging, bool disableInprocNod
             cache.QueryStartStops.Count.ShouldBe(graph.ProjectNodes.Count * 2);
         }
 
+        [Fact]
+        // Schedules different requests for the same BuildRequestConfiguration in parallel.
+        // The first batch of the requests are cache misses, the second batch are cache hits via proxy builds.
+        // The first batch is delayed so it starts intermingling with the second batch.
+        // This test ensures that scheduling proxy builds on the inproc node works nicely within the Scheduler
+        // if the BuildRequestConfigurations for those proxy builds have built before (or are still building) on
+        // the out of proc node.
+        // More details: https://github.com/dotnet/msbuild/pull/6635 
+        public void ProxyCacheHitsOnPreviousCacheMissesShouldWork()
+        {
+            var cacheNotApplicableTarget = "NATarget";
+            var cacheHitTarget = "CacheHitTarget";
+            var proxyTarget = "ProxyTarget";
+
+            var project =
+@$"
+<Project>
+    <Target Name='{cacheNotApplicableTarget}'>
+        <Exec Command=`{Helpers.GetSleepCommand(TimeSpan.FromMilliseconds(200))}` />
+        <Message Text='{cacheNotApplicableTarget} in $(MSBuildThisFile)' />
+    </Target>
+
+    <Target Name='{cacheHitTarget}'>
+        <Message Text='{cacheHitTarget} in $(MSBuildThisFile)' />
+    </Target>
+
+    <Target Name='{proxyTarget}'>
+        <Message Text='{proxyTarget} in $(MSBuildThisFile)' />
+    </Target>
+</Project>
+".Cleanup();
+
+            var projectPaths = Enumerable.Range(0, NativeMethodsShared.GetLogicalCoreCount())
+                .Select(i => _env.CreateFile($"project{i}.proj", project).Path)
+                .ToArray();
+
+            var cacheHitCount = 0;
+            var nonCacheHitCount = 0;
+
+            var buildParameters = new BuildParameters
+            {
+                ProjectCacheDescriptor = ProjectCacheDescriptor.FromInstance(
+                    new ConfigurableMockCache
+                    {
+                        GetCacheResultImplementation = (request, _, _) =>
+                        {
+                            var projectFile = request.ProjectFullPath;
+
+                            if (request.TargetNames.Contains(cacheNotApplicableTarget))
+                            {
+                                Interlocked.Increment(ref nonCacheHitCount);
+                                return Task.FromResult(CacheResult.IndicateNonCacheHit(CacheResultType.CacheNotApplicable));
+                            }
+                            else
+                            {
+                                Interlocked.Increment(ref cacheHitCount);
+                                return Task.FromResult(
+                                    CacheResult.IndicateCacheHit(
+                                        new ProxyTargets(new Dictionary<string, string> {{proxyTarget, cacheHitTarget}})));
+                            }
+                        }
+                    },
+                    projectPaths.Select(p => new ProjectGraphEntryPoint(p)).ToArray(),
+                    projectGraph: null),
+                MaxNodeCount = NativeMethodsShared.GetLogicalCoreCount()
+            };
+
+            using var buildSession = new Helpers.BuildManagerSession(_env, buildParameters);
+
+            var buildRequests = new List<(string, string)>();
+            buildRequests.AddRange(projectPaths.Select(r => (r, cacheNotApplicableTarget)));
+            buildRequests.AddRange(projectPaths.Select(r => (r, cacheHitTarget)));
+
+            var buildTasks = new List<Task<BuildResult>>();
+            foreach (var (projectPath, target) in buildRequests)
+            {
+                buildTasks.Add(buildSession.BuildProjectFileAsync(projectPath, new[] {target}));
+            }
+
+            foreach (var buildResult in buildTasks.Select(buildTask => buildTask.Result))
+            {
+                buildResult.Exception.ShouldBeNull();
+                buildResult.OverallResult.ShouldBe(BuildResultCode.Success);
+            }
+
+            buildSession.Logger.ProjectStartedEvents.Count.ShouldBe(2 * projectPaths.Length);
+
+            cacheHitCount.ShouldBe(projectPaths.Length);
+            nonCacheHitCount.ShouldBe(projectPaths.Length);
+        }
+
         private static void StringShouldContainSubstring(string aString, string substring, int expectedOccurrences)
         {
             aString.ShouldContain(substring);

src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs

@@ -4,6 +4,7 @@
 #nullable enable
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Reflection;
 using System.Threading;
@@ -102,6 +103,9 @@ private async Task BeginBuildAsync(ProjectCacheDescriptor? vsWorkaroundOverrideD
             {
                 SetState(ProjectCacheServiceState.BeginBuildStarted);
 
+                logger.LogMessage("Initializing project cache plugin", MessageImportance.Low);
+                var timer = Stopwatch.StartNew();
+
                 if (_projectCacheDescriptor.VsWorkaround)
                 {
                     logger.LogMessage("Running project cache with Visual Studio workaround");
@@ -118,6 +122,9 @@ await _projectCachePlugin.BeginBuildAsync(
                     logger,
                     _cancellationToken);
 
+                timer.Stop();
+                logger.LogMessage($"Finished initializing project cache plugin in {timer.Elapsed.TotalMilliseconds} ms", MessageImportance.Low);
+
                 SetState(ProjectCacheServiceState.BeginBuildFinished);
             }
             catch (Exception e)
@@ -413,8 +420,14 @@ public async Task ShutDown()
             {
                 SetState(ProjectCacheServiceState.ShutdownStarted);
 
+                logger.LogMessage("Shutting down project cache plugin", MessageImportance.Low);
+                var timer = Stopwatch.StartNew();
+
                 await _projectCachePlugin.EndBuildAsync(logger, _cancellationToken);
 
+                timer.Stop();
+                logger.LogMessage($"Finished shutting down project cache plugin in {timer.Elapsed.TotalMilliseconds} ms", MessageImportance.Low);
+
                 if (logger.HasLoggedErrors)
                 {
                     ProjectCacheException.ThrowForErrorLoggedInsideTheProjectCache("ProjectCacheShutdownFailed");

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

@@ -1385,7 +1385,7 @@ private void AssignUnscheduledRequestToNode(SchedulableRequest request, int node
 
             void WarnWhenProxyBuildsGetScheduledOnOutOfProcNode()
             {
-                if (request.IsProxyBuildRequest() && nodeId != InProcNodeId)
+                if (request.IsProxyBuildRequest() && nodeId != InProcNodeId && _schedulingData.CanScheduleRequestToNode(request, InProcNodeId))
                 {
                     ErrorUtilities.VerifyThrow(
                         _componentHost.BuildParameters.DisableInProcNode || _forceAffinityOutOfProc,
@@ -2107,7 +2107,11 @@ private NodeAffinity GetNodeAffinityForRequest(BuildRequest request)
                 return NodeAffinity.InProc;
             }
 
-            if (request.IsProxyBuildRequest())
+            ErrorUtilities.VerifyThrow(request.ConfigurationId != BuildRequestConfiguration.InvalidConfigurationId, "Requests should have a valid configuration id at this point");
+            // If this configuration has been previously built on an out of proc node, scheduling it on the inproc node can cause either an affinity mismatch error when
+            // there are other pending requests for the same configuration or "unscheduled requests remain in the presence of free out of proc nodes" errors if there's no pending requests.
+            // So only assign proxy builds to the inproc node if their config hasn't been previously assigned to an out of proc node.
+            if (_schedulingData.CanScheduleConfigurationToNode(request.ConfigurationId, InProcNodeId) && request.IsProxyBuildRequest())
             {
                 return NodeAffinity.InProc;
             }

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

@@ -647,7 +647,12 @@ public int GetAssignedNodeForRequestConfiguration(int configurationId)
         /// </summary>
         public bool CanScheduleRequestToNode(SchedulableRequest request, int nodeId)
         {
-            int requiredNodeId = GetAssignedNodeForRequestConfiguration(request.BuildRequest.ConfigurationId);
+            return CanScheduleConfigurationToNode(request.BuildRequest.ConfigurationId, nodeId);
+        }
+
+        public bool CanScheduleConfigurationToNode(int configurationId, int nodeId)
+        {
+            int requiredNodeId = GetAssignedNodeForRequestConfiguration(configurationId);
             return requiredNodeId == Scheduler.InvalidNodeId || requiredNodeId == nodeId;
         }