From d661b1d2f83e3e0770475d72cf5cc97c5a80baf2 Mon Sep 17 00:00:00 2001 From: Rainer Sigwald Date: Tue, 11 May 2021 13:01:54 -0500 Subject: [PATCH] Ensure context is not cached before logging info (#6437) Fixes #6436 which causes this crash in cases where MSBuild's result caching is turned on (generally this is for large builds in 32-bit MSBuild). ``` MSBUILD : error MSB1025: An internal failure occurred while running MSBuild. Microsoft.Build.Shared.InternalErrorException: MSB0001: Internal MSBuild Error: We shouldn't be accessing the ProjectInstance when the configuration is cached. at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Exception innerException, Object[] args) at Microsoft.Build.BackEnd.BuildRequestConfiguration.get_Project() at Microsoft.Build.BackEnd.Logging.NodeLoggingContext.LogProjectStarted(BuildRequest request, BuildRequestConfiguration configuration) at Microsoft.Build.BackEnd.Logging.NodeLoggingContext.LogRequestHandledFromCache(BuildRequest request, BuildRequestConfiguration configuration, BuildResult result) at Microsoft.Build.BackEnd.Scheduler.LogRequestHandledFromCache(BuildRequest request, BuildResult result) at Microsoft.Build.BackEnd.Scheduler.HandleRequestBlockedByNewRequests(SchedulableRequest parentRequest, BuildRequestBlocker blocker, List`1 responses) at Microsoft.Build.BackEnd.Scheduler.ReportRequestBlocked(Int32 nodeId, BuildRequestBlocker blocker) at Microsoft.Build.Execution.BuildManager.HandleNewRequest(Int32 node, BuildRequestBlocker blocker) at Microsoft.Build.Execution.BuildManager.ProcessPacket(Int32 node, INodePacket packet) at Microsoft.Build.Execution.BuildManager.<>c__DisplayClass76_0.b__0() at Microsoft.Build.Execution.BuildManager.ProcessWorkQueue(Action action) --- End of stack trace from previous location where exception was thrown --- at Microsoft.Build.Execution.BuildManager.EndBuild() ``` Bump version to 16.9.2 because we actually shipped a .1 but branded it .0. --- eng/Versions.props | 2 +- src/Build.UnitTests/BinaryLogger_Tests.cs | 51 +++++++++++++++++++ .../Components/Logging/NodeLoggingContext.cs | 8 ++- 3 files changed, 59 insertions(+), 2 deletions(-) diff --git a/eng/Versions.props b/eng/Versions.props index 041ae15c3e2..0b1046359b4 100644 --- a/eng/Versions.props +++ b/eng/Versions.props @@ -2,7 +2,7 @@ - 16.9.0release + 16.9.2release 15.1.0.0 preview true diff --git a/src/Build.UnitTests/BinaryLogger_Tests.cs b/src/Build.UnitTests/BinaryLogger_Tests.cs index ec95009bec1..bc2c161d226 100644 --- a/src/Build.UnitTests/BinaryLogger_Tests.cs +++ b/src/Build.UnitTests/BinaryLogger_Tests.cs @@ -1,5 +1,13 @@ using System; +using System.Collections.Generic; + +using Microsoft.Build.Evaluation; +using Microsoft.Build.Execution; +using Microsoft.Build.Framework; using Microsoft.Build.Logging; + +using Shouldly; + using Xunit; using Xunit.Abstractions; @@ -92,6 +100,49 @@ public void BinaryLoggerShouldNotThrowWhenMetadataCannotBeExpanded() ObjectModelHelpers.BuildProjectExpectSuccess(project, binaryLogger); } + /// + /// Regression test for https://github.com/dotnet/msbuild/issues/6323. + /// + /// + /// This isn't strictly a binlog test, but it fits here because + /// all log event types will be used when the binlog is attached. + /// + [Fact] + public void MessagesCanBeLoggedWhenProjectsAreCached() + { + using var env = TestEnvironment.Create(); + + env.SetEnvironmentVariable("MSBUILDDEBUGFORCECACHING", "1"); + + using var buildManager = new BuildManager(); + + var binaryLogger = new BinaryLogger + { + Parameters = $"LogFile={_logFile}" + }; + + // To trigger #6323, there must be at least two project instances. + var referenceProject = _env.CreateTestProjectWithFiles("reference.proj", @" + + + + + "); + + var entryProject = _env.CreateTestProjectWithFiles("entry.proj", $@" + + + + + + + "); + + buildManager.Build(new BuildParameters() { Loggers = new ILogger[] { binaryLogger } }, + new BuildRequestData(entryProject.ProjectFile, new Dictionary(), null, new string[] { "BuildSelf" }, null)) + .OverallResult.ShouldBe(BuildResultCode.Success); + } + public void Dispose() { diff --git a/src/Build/BackEnd/Components/Logging/NodeLoggingContext.cs b/src/Build/BackEnd/Components/Logging/NodeLoggingContext.cs index 05c5ae53708..0b55b80359a 100644 --- a/src/Build/BackEnd/Components/Logging/NodeLoggingContext.cs +++ b/src/Build/BackEnd/Components/Logging/NodeLoggingContext.cs @@ -69,7 +69,13 @@ internal ProjectLoggingContext LogProjectStarted(BuildRequestEntry requestEntry) internal ProjectLoggingContext LogProjectStarted(BuildRequest request, BuildRequestConfiguration configuration) { ErrorUtilities.VerifyThrow(this.IsValid, "Build not started."); - return new ProjectLoggingContext(this, request, configuration.ProjectFullPath, configuration.ToolsVersion, request.ParentBuildEventContext, configuration.Project?.EvaluationId ?? BuildEventContext.InvalidEvaluationId); + + // If we can retrieve the evaluationId from the project, do so. Don't if it's not available or + // if we'd have to retrieve it from the cache in order to access it. + // Order is important here because the Project getter will throw if IsCached. + int evaluationId = (configuration != null && !configuration.IsCached && configuration.Project != null) ? configuration.Project.EvaluationId : BuildEventContext.InvalidEvaluationId; + + return new ProjectLoggingContext(this, request, configuration.ProjectFullPath, configuration.ToolsVersion, request.ParentBuildEventContext, evaluationId); } ///