ToolTasks Don't Log MSB4181 When Terminated

[benvillalobos]

Fixes #5508

Context

Originally seen with the Exec and csc tasks. When any tooltask is terminated early, it would simply return false. This goes against our "rule" that ToolTasks should return !Log.HasLoggedErrors.

Changes Made

ToolTasks return !Log.HasLoggedErrors when cancelled.

Testing

Updated two tests that expected Exec to fail when it timed out (timing out follows the same behavior that cancelling does).

Also tested locally by cancelling a build of this repo. See the diff when cancelling msbuild msbuild.dev.slnf

Before

after

Notes

I intentionally didn't change every return false codepath to keep this fix contained. We can tackle other issues with ToolTask as they arise.

[rainersigwald]

This definitely solves the problem but I'm not sure it's conceptually right: the task was cancelled before completion, so shouldn't it return false as in I did not succeed?

Is the "was cancellation requested" state available at the time when we check failure/has-logged-error and log the new message?

[benvillalobos]

Is the "was cancellation requested" state available at the time when we check failure/has-logged-error and log the new message?

This is the code that logs the warning
https://github.com/dotnet/msbuild/blob/main/src/Utilities/ToolTask.cs#L939-L949

Can a task be cancelled outside of the user's control? That's not something I considered when writing this.

It really depends how we want to view this task. I see a tooltask being (manually) cancelled as "I didn't fail, so as long as I didn't log an error I'm good"

[rainersigwald]

I was thinking more like wrapping a if (!_cancellationToken.IsCancellationRequested) around the actual error message here:

msbuild/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs

Lines 940 to 958 in a7d5790

	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 (_continueOnError == ContinueOnError.WarnAndContinue)
	{
	taskLoggingContext.LogWarning(null,
	new BuildEventFileInfo(_targetChildInstance.Location),
	"TaskReturnedFalseButDidNotLogError",
	_taskNode.Name);
	taskLoggingContext.LogComment(MessageImportance.Normal, "ErrorConvertedIntoWarning");
	}
	else
	{
	taskLoggingContext.LogError(new BuildEventFileInfo(_targetChildInstance.Location),
	"TaskReturnedFalseButDidNotLogError",
	_taskNode.Name);
	}
	}

(but I didn't validate that that actually worked).

My mental model for a task is "return true: everything completed satisfactorily. return false: something somewhere went wrong". But it's a bit ambiguous.

[benvillalobos]

My mental model for a task is "return true: everything completed satisfactorily. return false: something somewhere went wrong". But it's a bit ambiguous.

I'm a bit confused here. The RemoveDir change is a good example. It used to return true only if all the directories were successfully deleted. That PR is pushing for having it return true even if some directories weren't deleted, so long as we didn't log an error. which is somewhere in the middle of "return true: everything completed satisfactorily. return false: something somewhere went wrong"

I like your suggested solution better though since it's less break-y, so I'll give that a shot.

[benvillalobos]

Your idea works 🚀 and avoids a fundamental change to all tooltasks. Not exactly sure how to test this though, my local test runs a sleep.exe that wouldn't exist in a unit test. Any ideas?

[rainersigwald]

We have a helper for that, try something like:

msbuild/src/Build.UnitTests/BackEnd/BuildManager_Tests.cs

Lines 1523 to 1533 in a7d5790

	public void CancelledBuild()
	{
	Console.WriteLine("Starting CancelledBuild test that is known to hang.");
	string contents = CleanupFileContents(@"
	<Project xmlns='msbuildnamespace' ToolsVersion='msbuilddefaulttoolsversion'>
	<Target Name='test'>
	<Exec Command='" + Helpers.GetSleepCommand(TimeSpan.FromSeconds(60)) + @"'/>
	<Message Text='[errormessage]'/>
	</Target>
	</Project>
	");

[rainersigwald]

Is the right place for this here or in the big ugly chained if above this level?

[benvillalobos]

I was hoping to avoid making that chain worse, but you're right. A WarnAndContinue Exec task would log MSB4181 as a warning if it was cancelled.

[rainersigwald]

These comments . . . 🧑🏻‍🍳💋🤌🏻

(but . . . is there a test we can add for this?)