diff --git a/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs b/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs index 6f66f263d26..c91df2ca317 100644 --- a/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs +++ b/src/Build.UnitTests/BackEnd/TaskBuilder_Tests.cs @@ -16,6 +16,7 @@ using Microsoft.Build.Execution; using Microsoft.Build.Framework; using Microsoft.Build.Shared; +using Microsoft.Build.UnitTests.Shared; using Shouldly; using Xunit; using Xunit.Abstractions; @@ -84,6 +85,32 @@ public void TasksAreDiscoveredWhenTaskConditionTrue() logger.AssertLogDoesntContain("Made it"); } + [Fact] + public void TasksOnlyLogStartedEventOnceEach() + { + using TestEnvironment env = TestEnvironment.Create(); + string projectFileContents = ObjectModelHelpers.CleanupFileContents( + @" + + + + "); + + TransientTestFile projectFile = env.CreateFile("myProj.proj", projectFileContents); + env.SetEnvironmentVariable("DOTNET_PERFLOG_DIR", @"C:\Users\namytelk\Desktop"); + + string results = RunnerUtilities.ExecMSBuild(projectFile.Path + " /v:diag", out bool success); + + int count = 0; + for (int index = results.IndexOf("Task \"Message\""); index >= 0; index = results.IndexOf("Task \"Message\"", index)) + { + count++; + index += 14; // Skip to the end of this string + } + + count.ShouldBe(1); + } + /// /// Tests that when the task condition is false, Execute still returns true even though we never loaded /// the task. We verify that we never loaded the task because if we did try, the task load itself would diff --git a/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs b/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs index b83da0aa245..f8768988732 100644 --- a/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs +++ b/src/Build/BackEnd/Components/RequestBuilder/TaskBuilder.cs @@ -391,12 +391,6 @@ private async Task ExecuteBucket(TaskHost taskHost, ItemBucket b } // Some tests do not provide an actual taskNode; checking if _taskNode == null prevents those tests from failing. - if (MSBuildEventSource.Log.IsEnabled()) - { - TaskLoggingContext taskLoggingContext = _targetLoggingContext.LogTaskBatchStarted(_projectFullPath, _targetChildInstance); - MSBuildEventSource.Log.ExecuteTaskStart(_taskNode?.Name, taskLoggingContext.BuildEventContext.TaskId); - } - // If this is an Intrinsic task, it gets handled in a special fashion. if (_taskNode == null) { @@ -433,6 +427,7 @@ private async Task ExecuteBucket(TaskHost taskHost, ItemBucket b if (requirements != null) { TaskLoggingContext taskLoggingContext = _targetLoggingContext.LogTaskBatchStarted(_projectFullPath, _targetChildInstance); + MSBuildEventSource.Log.ExecuteTaskStart(_taskNode?.Name, taskLoggingContext.BuildEventContext.TaskId); _buildRequestEntry.Request.CurrentTaskContext = taskLoggingContext.BuildEventContext; try @@ -487,6 +482,8 @@ private async Task ExecuteBucket(TaskHost taskHost, ItemBucket b // We coerce the failing result to a successful result. taskResult = new WorkUnitResult(WorkUnitResultCode.Success, taskResult.ActionCode, taskResult.Exception); } + + MSBuildEventSource.Log.ExecuteTaskStop(_taskNode?.Name, taskLoggingContext.BuildEventContext.TaskId); } } } @@ -514,13 +511,6 @@ private async Task ExecuteBucket(TaskHost taskHost, ItemBucket b } } - // Some tests do not provide an actual taskNode; checking if _taskNode == null prevents those tests from failing. - if (MSBuildEventSource.Log.IsEnabled()) - { - TaskLoggingContext taskLoggingContext = _targetLoggingContext.LogTaskBatchStarted(_projectFullPath, _targetChildInstance); - MSBuildEventSource.Log.ExecuteTaskStop(_taskNode?.Name, taskLoggingContext.BuildEventContext.TaskId); - } - return taskResult; }