Only log task started once (#8265)

Changes Made Only log task started once, even when MSBuildEventSource.Log.IsEnabled() Testing None Notes Co-authored-by: Forgind <[email protected]>
dotnet · Mar 2, 2023 · e0f4434 · e0f4434
1 parent ed8d50f
commit e0f4434
Show file tree

Hide file tree

Showing 2 changed files with 30 additions and 13 deletions.
diff --git 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(
+            @"<Project>
+              <Target Name='t'>
+                  <Message Text='Made it'/>
+              </Target>
+            </Project>");
+
+            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);
+        }
+
         /// <summary>
         /// 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
@@ -391,12 +391,6 @@ private async Task<WorkUnitResult> 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<WorkUnitResult> 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<WorkUnitResult> 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<WorkUnitResult> 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;
         }