From e06a995a76a8bd86f5734b76c064b6eed4454a9f Mon Sep 17 00:00:00 2001 From: Ben Villalobos <4691428+BenVillalobos@users.noreply.github.com> Date: Thu, 14 Oct 2021 14:08:39 -0700 Subject: [PATCH 1/5] Tooltasks return !HasLoggedErrors when terminated --- src/Tasks.UnitTests/Exec_Tests.cs | 13 +++++++------ src/Utilities/ToolTask.cs | 2 +- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/src/Tasks.UnitTests/Exec_Tests.cs b/src/Tasks.UnitTests/Exec_Tests.cs index 67fc7772e5b..0633635f47f 100644 --- a/src/Tasks.UnitTests/Exec_Tests.cs +++ b/src/Tasks.UnitTests/Exec_Tests.cs @@ -154,13 +154,13 @@ public void Timeout() exec.Timeout = 5; bool result = exec.Execute(); - Assert.False(result); - Assert.Equal(expectedExitCode, exec.ExitCode); + // When a tooltask times out, it behaves the same as when it is cancelled and returns !Log.HasLoggedErrors + result.ShouldBeTrue(); + exec.ExitCode.ShouldBe(expectedExitCode); ((MockEngine)exec.BuildEngine).AssertLogContains("MSB5002"); - Assert.Equal(1, ((MockEngine)exec.BuildEngine).Warnings); - + ((MockEngine)exec.BuildEngine).Warnings.ShouldBe(1); // ToolTask does not log an error on timeout. - Assert.Equal(0, ((MockEngine)exec.BuildEngine).Errors); + ((MockEngine)exec.BuildEngine).Errors.ShouldBe(0); } [Fact] @@ -171,7 +171,8 @@ public void TimeoutFailsEvenWhenExitCodeIsIgnored() exec.IgnoreExitCode = true; bool result = exec.Execute(); - result.ShouldBeFalse(); + // When a tooltask times out, it behaves the same as when it is cancelled and returns !Log.HasLoggedErrors + result.ShouldBeTrue(); MockEngine mockEngine = (MockEngine)exec.BuildEngine; mockEngine.AssertLogContains("MSB5002"); mockEngine.Warnings.ShouldBe(1); diff --git a/src/Utilities/ToolTask.cs b/src/Utilities/ToolTask.cs index e7766038d11..bda5bd2118c 100644 --- a/src/Utilities/ToolTask.cs +++ b/src/Utilities/ToolTask.cs @@ -1522,7 +1522,7 @@ public override bool Execute() // Raise a comment event to notify that the process completed if (_terminatedTool) { - return false; + return !Log.HasLoggedErrors; } else if (ExitCode != 0) { From 61f1a3ee87c82dbdf3e2b77a09095887c84714e9 Mon Sep 17 00:00:00 2001 From: Ben Villalobos <4691428+BenVillalobos@users.noreply.github.com> Date: Mon, 18 Oct 2021 14:52:30 -0700 Subject: [PATCH 2/5] Revert "Tooltasks return !HasLoggedErrors when terminated" This reverts commit e06a995a76a8bd86f5734b76c064b6eed4454a9f. --- src/Tasks.UnitTests/Exec_Tests.cs | 13 ++++++------- src/Utilities/ToolTask.cs | 2 +- 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/src/Tasks.UnitTests/Exec_Tests.cs b/src/Tasks.UnitTests/Exec_Tests.cs index 0633635f47f..67fc7772e5b 100644 --- a/src/Tasks.UnitTests/Exec_Tests.cs +++ b/src/Tasks.UnitTests/Exec_Tests.cs @@ -154,13 +154,13 @@ public void Timeout() exec.Timeout = 5; bool result = exec.Execute(); - // When a tooltask times out, it behaves the same as when it is cancelled and returns !Log.HasLoggedErrors - result.ShouldBeTrue(); - exec.ExitCode.ShouldBe(expectedExitCode); + Assert.False(result); + Assert.Equal(expectedExitCode, exec.ExitCode); ((MockEngine)exec.BuildEngine).AssertLogContains("MSB5002"); - ((MockEngine)exec.BuildEngine).Warnings.ShouldBe(1); + Assert.Equal(1, ((MockEngine)exec.BuildEngine).Warnings); + // ToolTask does not log an error on timeout. - ((MockEngine)exec.BuildEngine).Errors.ShouldBe(0); + Assert.Equal(0, ((MockEngine)exec.BuildEngine).Errors); } [Fact] @@ -171,8 +171,7 @@ public void TimeoutFailsEvenWhenExitCodeIsIgnored() exec.IgnoreExitCode = true; bool result = exec.Execute(); - // When a tooltask times out, it behaves the same as when it is cancelled and returns !Log.HasLoggedErrors - result.ShouldBeTrue(); + result.ShouldBeFalse(); MockEngine mockEngine = (MockEngine)exec.BuildEngine; mockEngine.AssertLogContains("MSB5002"); mockEngine.Warnings.ShouldBe(1); diff --git a/src/Utilities/ToolTask.cs b/src/Utilities/ToolTask.cs index bda5bd2118c..e7766038d11 100644 --- a/src/Utilities/ToolTask.cs +++ b/src/Utilities/ToolTask.cs @@ -1522,7 +1522,7 @@ public override bool Execute() // Raise a comment event to notify that the process completed if (_terminatedTool) { - return !Log.HasLoggedErrors; + return false; } else if (ExitCode != 0) { From 8598f2721446a94edaf8cb6276005b4570430072 Mon Sep 17 00:00:00 2001 From: Ben Villalobos <4691428+BenVillalobos@users.noreply.github.com> Date: Mon, 18 Oct 2021 14:53:03 -0700 Subject: [PATCH 3/5] Don't log MSB4181 when a task is cancelled. --- src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs b/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs index 5fdd1a3e145..2048676d12f 100644 --- a/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs +++ b/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs @@ -949,7 +949,7 @@ private async Task ExecuteInstantiatedTask(ITaskExecutionHost ta taskLoggingContext.LogComment(MessageImportance.Normal, "ErrorConvertedIntoWarning"); } - else + else if (!(_cancellationToken.CanBeCanceled && _cancellationToken.IsCancellationRequested)) { taskLoggingContext.LogError(new BuildEventFileInfo(_targetChildInstance.Location), "TaskReturnedFalseButDidNotLogError", From 1650c0c9bb0b362c2674d1b31ff47504a0f940c2 Mon Sep 17 00:00:00 2001 From: Ben Villalobos <4691428+BenVillalobos@users.noreply.github.com> Date: Tue, 19 Oct 2021 15:00:47 -0700 Subject: [PATCH 4/5] Tidy up MSB4181 conditions --- .../BackEnd/Components/RequestBuilder/TaskBuilder.cs | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs b/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs index 2048676d12f..c6ac1c6d297 100644 --- a/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs +++ b/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs @@ -938,8 +938,14 @@ private async Task ExecuteInstantiatedTask(ITaskExecutionHost ta // that is logged as an error. MSBuild tasks are an exception because // errors are not logged directly from them, but the tasks spawned by them. IBuildEngine be = host.TaskInstance.BuildEngine; - if (taskReturned && !taskResult && !taskLoggingContext.HasLoggedErrors && (be is TaskHost th ? th.BuildRequestsSucceeded : false) && (be is IBuildEngine7 be7 ? !be7.AllowFailureWithoutError : true)) + if (taskReturned // if the task returned + && !taskResult // and it returned false + && !taskLoggingContext.HasLoggedErrors // and it didn't log any errors + && (be is TaskHost th ? th.BuildRequestsSucceeded : false) + && (be is IBuildEngine7 be7 ? !be7.AllowFailureWithoutError : true) // and it's not allowed to fail unless it logs an error + && !(_cancellationToken.CanBeCanceled && _cancellationToken.IsCancellationRequested)) // and it wasn't cancelled { + // Then decide how to log MSB4181 if (_continueOnError == ContinueOnError.WarnAndContinue) { taskLoggingContext.LogWarning(null, @@ -949,7 +955,7 @@ private async Task ExecuteInstantiatedTask(ITaskExecutionHost ta taskLoggingContext.LogComment(MessageImportance.Normal, "ErrorConvertedIntoWarning"); } - else if (!(_cancellationToken.CanBeCanceled && _cancellationToken.IsCancellationRequested)) + else { taskLoggingContext.LogError(new BuildEventFileInfo(_targetChildInstance.Location), "TaskReturnedFalseButDidNotLogError", From 997c70370a3d61eaa0807157fee5c8b2db73dfe8 Mon Sep 17 00:00:00 2001 From: Ben Villalobos <4691428+BenVillalobos@users.noreply.github.com> Date: Fri, 22 Oct 2021 12:46:12 -0700 Subject: [PATCH 5/5] Add regression test --- .../BackEnd/TaskBuilder_Tests.cs | 58 +++++++++++++++++++ 1 file changed, 58 insertions(+) diff --git a/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs b/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs index 486352af3f2..87152257402 100644 --- a/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs +++ b/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs @@ -22,6 +22,7 @@ using Shouldly; using Xunit; using Xunit.Abstractions; +using System.Threading; namespace Microsoft.Build.UnitTests.BackEnd { @@ -107,6 +108,63 @@ public void TasksNotDiscoveredWhenTaskConditionFalse() logger.AssertLogContains("Made it"); } + [Fact] + public void CanceledTasksDoNotLogMSB4181() + { + using (TestEnvironment env = TestEnvironment.Create(_testOutput)) + { + BuildManager manager = new BuildManager(); + ProjectCollection collection = new ProjectCollection(); + + string contents = @" + + + + + "; + + MockLogger logger = new MockLogger(_testOutput); + + var project = new Project(XmlReader.Create(new StringReader(contents)), null, MSBuildConstants.CurrentToolsVersion, collection) + { + FullPath = env.CreateFile().Path + }; + + var _parameters = new BuildParameters + { + ShutdownInProcNodeOnBuildFinish = true, + Loggers = new ILogger[] { logger }, + EnableNodeReuse = false + }; + ; + + BuildRequestData data = new BuildRequestData(project.CreateProjectInstance(), new string[] { "test" }, collection.HostServices); + manager.BeginBuild(_parameters); + BuildSubmission asyncResult = manager.PendBuildRequest(data); + asyncResult.ExecuteAsync(null, null); + Thread.Sleep(500); + manager.CancelAllSubmissions(); + asyncResult.WaitHandle.WaitOne(); + BuildResult result = asyncResult.BuildResult; + manager.EndBuild(); + + // No errors from cancelling a build. + logger.ErrorCount.ShouldBe(0); + // Warn because the task is being cancelled. + // NOTE: This assertion will fail when debugging into it because "waiting on exec to cancel" warning will be logged. + logger.WarningCount.ShouldBe(1); + // Build failed because it was cancelled. + result.OverallResult.ShouldBe(BuildResultCode.Failure); + // Should log "Cmd being cancelled because build was cancelled" warning + logger.AssertLogContains("MSB5021"); + // Should NOT log "exec failed without logging error" + logger.AssertLogDoesntContain("MSB4181"); + + collection.Dispose(); + manager.Dispose(); + } + } + /// /// Verify when task outputs are overridden the override messages are correctly displayed ///