Add TargetSkipReason and OriginalBuildEventContext to TargetSkippedEv…

…entArgs (#6402)

We weren't logging TargetSkippedEventArgs in two cases: when the target was satisfied from cache (previously built), or when the outputs were up-to-date. We were logging simple messages. Switch to logging TargetSkippedEventArgs in these cases as well.

Add a new TargetSkipReason enum to indicate why the target was skipped. Store and serialize it for node packet translator and binary logger.

When logging a TargetSkippedEventArgs because a target was built previously it is also useful to find the original target invocation (e.g. to see the target outputs). Add OriginalBuildEventContext to TargetResult and ensure it is translated properly. Add OriginalBuildEventContext on TargetSkippedEventArgs and serialize that as well (both node packet translator and binary logger).

Note that if the target didn't build because the Condition was false, the OriginalBuildEventContext will be a project context, not a target context.

We have to increment the binlog file format version to 14 to add the two new fields.

Implement BuildEventContext.ToString() for easier debugging.

Add an internal setter for Importance on BuildMessageEventArgs.

We were missing unit-tests for node packet translation of TargetSkippedEventArgs. Add test.

Fixes #5475

ref/Microsoft.Build.Framework/net/Microsoft.Build.Framework.cs

@@ -70,6 +70,7 @@ public BuildEventContext(int submissionId, int nodeId, int evaluationId, int pro
         public override int GetHashCode() { throw null; }
         public static bool operator ==(Microsoft.Build.Framework.BuildEventContext left, Microsoft.Build.Framework.BuildEventContext right) { throw null; }
         public static bool operator !=(Microsoft.Build.Framework.BuildEventContext left, Microsoft.Build.Framework.BuildEventContext right) { throw null; }
+        public override string ToString() { throw null; }
     }
     public partial class BuildFinishedEventArgs : Microsoft.Build.Framework.BuildStatusEventArgs
     {
@@ -580,11 +581,21 @@ public TargetSkippedEventArgs(string message, params object[] messageArgs) { }
         public string Condition { get { throw null; } set { } }
         public string EvaluatedCondition { get { throw null; } set { } }
         public override string Message { get { throw null; } }
+        public Microsoft.Build.Framework.BuildEventContext OriginalBuildEventContext { get { throw null; } set { } }
         public bool OriginallySucceeded { get { throw null; } set { } }
         public string ParentTarget { get { throw null; } set { } }
+        public Microsoft.Build.Framework.TargetSkipReason SkipReason { get { throw null; } set { } }
         public string TargetFile { get { throw null; } set { } }
         public string TargetName { get { throw null; } set { } }
     }
+    public enum TargetSkipReason
+    {
+        None = 0,
+        PreviouslyBuiltSuccessfully = 1,
+        PreviouslyBuiltUnsuccessfully = 2,
+        OutputsUpToDate = 3,
+        ConditionWasFalse = 4,
+    }
     public partial class TargetStartedEventArgs : Microsoft.Build.Framework.BuildStatusEventArgs
     {
         protected TargetStartedEventArgs() { }

ref/Microsoft.Build.Framework/netstandard/Microsoft.Build.Framework.cs

@@ -70,6 +70,7 @@ public BuildEventContext(int submissionId, int nodeId, int evaluationId, int pro
         public override int GetHashCode() { throw null; }
         public static bool operator ==(Microsoft.Build.Framework.BuildEventContext left, Microsoft.Build.Framework.BuildEventContext right) { throw null; }
         public static bool operator !=(Microsoft.Build.Framework.BuildEventContext left, Microsoft.Build.Framework.BuildEventContext right) { throw null; }
+        public override string ToString() { throw null; }
     }
     public partial class BuildFinishedEventArgs : Microsoft.Build.Framework.BuildStatusEventArgs
     {
@@ -579,11 +580,21 @@ public TargetSkippedEventArgs(string message, params object[] messageArgs) { }
         public string Condition { get { throw null; } set { } }
         public string EvaluatedCondition { get { throw null; } set { } }
         public override string Message { get { throw null; } }
+        public Microsoft.Build.Framework.BuildEventContext OriginalBuildEventContext { get { throw null; } set { } }
         public bool OriginallySucceeded { get { throw null; } set { } }
         public string ParentTarget { get { throw null; } set { } }
+        public Microsoft.Build.Framework.TargetSkipReason SkipReason { get { throw null; } set { } }
         public string TargetFile { get { throw null; } set { } }
         public string TargetName { get { throw null; } set { } }
     }
+    public enum TargetSkipReason
+    {
+        None = 0,
+        PreviouslyBuiltSuccessfully = 1,
+        PreviouslyBuiltUnsuccessfully = 2,
+        OutputsUpToDate = 3,
+        ConditionWasFalse = 4,
+    }
     public partial class TargetStartedEventArgs : Microsoft.Build.Framework.BuildStatusEventArgs
     {
         protected TargetStartedEventArgs() { }

src/Build.UnitTests/BackEnd/NodePackets_Tests.cs

@@ -52,6 +52,7 @@ public void VerifyEventType()
             BuildErrorEventArgs error = new BuildErrorEventArgs("SubCategoryForSchemaValidationErrors", "MSB4000", "file", 1, 2, 3, 4, "message", "help", "sender");
             TargetStartedEventArgs targetStarted = new TargetStartedEventArgs("message", "help", "targetName", "ProjectFile", "targetFile");
             TargetFinishedEventArgs targetFinished = new TargetFinishedEventArgs("message", "help", "targetName", "ProjectFile", "targetFile", true);
+            TargetSkippedEventArgs targetSkipped = CreateTargetSkipped();
             ProjectStartedEventArgs projectStarted = new ProjectStartedEventArgs(-1, "message", "help", "ProjectFile", "targetNames", null, null, null);
             ProjectFinishedEventArgs projectFinished = new ProjectFinishedEventArgs("message", "help", "ProjectFile", true);
             ExternalProjectStartedEventArgs externalStartedEvent = new ExternalProjectStartedEventArgs("message", "help", "senderName", "projectFile", "targetNames");
@@ -69,6 +70,7 @@ public void VerifyEventType()
             VerifyLoggingPacket(error, LoggingEventType.BuildErrorEvent);
             VerifyLoggingPacket(targetStarted, LoggingEventType.TargetStartedEvent);
             VerifyLoggingPacket(targetFinished, LoggingEventType.TargetFinishedEvent);
+            VerifyLoggingPacket(targetSkipped, LoggingEventType.TargetSkipped);
             VerifyLoggingPacket(projectStarted, LoggingEventType.ProjectStartedEvent);
             VerifyLoggingPacket(projectFinished, LoggingEventType.ProjectFinishedEvent);
             VerifyLoggingPacket(evaluationStarted, LoggingEventType.ProjectEvaluationStartedEvent);
@@ -176,6 +178,26 @@ private static TaskParameterEventArgs CreateTaskParameter()
             return result;
         }
 
+        private static TargetSkippedEventArgs CreateTargetSkipped()
+        {
+            var result = new TargetSkippedEventArgs(message: null)
+            {
+                BuildReason = TargetBuiltReason.DependsOn,
+                SkipReason = TargetSkipReason.PreviouslyBuiltSuccessfully,
+                BuildEventContext = CreateBuildEventContext(),
+                OriginalBuildEventContext = CreateBuildEventContext(),
+                Condition = "$(Condition) == 'true'",
+                EvaluatedCondition = "'true' == 'true'",
+                Importance = MessageImportance.Normal,
+                OriginallySucceeded = true,
+                ProjectFile = "1.proj",
+                TargetFile = "1.proj",
+                TargetName = "Build",
+                ParentTarget = "ParentTarget"
+            };
+            return result;
+        }
+
         /// <summary>
         /// Tests serialization of LogMessagePacket with each kind of event type.
         /// </summary>
@@ -209,7 +231,8 @@ public void TestTranslation()
                     new ProjectFinishedEventArgs("message", "help", "ProjectFile", true),
                     new ExternalProjectStartedEventArgs("message", "help", "senderName", "projectFile", "targetNames"),
                     CreateProjectEvaluationStarted(),
-                    CreateProjectEvaluationFinished()
+                    CreateProjectEvaluationFinished(),
+                    CreateTargetSkipped()
                 };
 
                 foreach (BuildEventArgs arg in testArgs)
@@ -414,6 +437,23 @@ private void CompareLogMessagePackets(LogMessagePacket left, LogMessagePacket ri
                     Assert.Equal(leftTargetStarted.TargetName, rightTargetStarted.TargetName);
                     break;
 
+                case LoggingEventType.TargetSkipped:
+                    TargetSkippedEventArgs leftTargetSkipped = left.NodeBuildEvent.Value.Value as TargetSkippedEventArgs;
+                    TargetSkippedEventArgs rightTargetSkipped = right.NodeBuildEvent.Value.Value as TargetSkippedEventArgs;
+                    Assert.Equal(leftTargetSkipped.BuildReason, rightTargetSkipped.BuildReason);
+                    Assert.Equal(leftTargetSkipped.SkipReason, rightTargetSkipped.SkipReason);
+                    Assert.Equal(leftTargetSkipped.BuildEventContext, rightTargetSkipped.BuildEventContext);
+                    Assert.Equal(leftTargetSkipped.OriginalBuildEventContext, rightTargetSkipped.OriginalBuildEventContext);
+                    Assert.Equal(leftTargetSkipped.Condition, rightTargetSkipped.Condition);
+                    Assert.Equal(leftTargetSkipped.EvaluatedCondition, rightTargetSkipped.EvaluatedCondition);
+                    Assert.Equal(leftTargetSkipped.Importance, rightTargetSkipped.Importance);
+                    Assert.Equal(leftTargetSkipped.OriginallySucceeded, rightTargetSkipped.OriginallySucceeded);
+                    Assert.Equal(leftTargetSkipped.ProjectFile, rightTargetSkipped.ProjectFile);
+                    Assert.Equal(leftTargetSkipped.TargetFile, rightTargetSkipped.TargetFile);
+                    Assert.Equal(leftTargetSkipped.TargetName, rightTargetSkipped.TargetName);
+                    Assert.Equal(leftTargetSkipped.ParentTarget, rightTargetSkipped.ParentTarget);
+                    break;
+
                 case LoggingEventType.TaskCommandLineEvent:
                     TaskCommandLineEventArgs leftCommand = left.NodeBuildEvent.Value.Value as TaskCommandLineEventArgs;
                     TaskCommandLineEventArgs rightCommand = right.NodeBuildEvent.Value.Value as TaskCommandLineEventArgs;

src/Build.UnitTests/BackEnd/TargetResult_Tests.cs

@@ -89,15 +89,20 @@ public void TestTranslationNoException()
         {
             TaskItem item = new TaskItem("foo", "bar.proj");
             item.SetMetadata("a", "b");
+            var buildEventContext = new Framework.BuildEventContext(1, 2, 3, 4, 5, 6, 7);
 
-            TargetResult result = new TargetResult(new TaskItem[] { item }, BuildResultUtilities.GetStopWithErrorResult());
+            TargetResult result = new TargetResult(
+                new TaskItem[] { item },
+                BuildResultUtilities.GetStopWithErrorResult(),
+                buildEventContext);
 
             ((ITranslatable)result).Translate(TranslationHelpers.GetWriteTranslator());
             TargetResult deserializedResult = TargetResult.FactoryForDeserialization(TranslationHelpers.GetReadTranslator());
 
             Assert.Equal(result.ResultCode, deserializedResult.ResultCode);
             Assert.True(TranslationHelpers.CompareCollections(result.Items, deserializedResult.Items, TaskItemComparer.Instance));
             Assert.True(TranslationHelpers.CompareExceptions(result.Exception, deserializedResult.Exception));
+            Assert.Equal(result.OriginalBuildEventContext, deserializedResult.OriginalBuildEventContext);
         }
 
         /// <summary>

src/Build.UnitTests/BuildEventArgsSerialization_Tests.cs

@@ -447,20 +447,31 @@ public void RoundtripTargetSkippedEventArgs()
                 ProjectFile = "foo.csproj",
                 TargetName = "target",
                 ParentTarget = "bar",
-                BuildReason = TargetBuiltReason.DependsOn
+                BuildReason = TargetBuiltReason.DependsOn,
+                SkipReason = TargetSkipReason.PreviouslyBuiltSuccessfully,
+                Condition = "$(condition) == true",
+                EvaluatedCondition = "true == true",
+                OriginalBuildEventContext = new BuildEventContext(1, 2, 3, 4, 5, 6, 7),
+                OriginallySucceeded = false,
+                TargetFile = "foo.csproj"
             };
 
             Roundtrip(args,
+                e => e.BuildEventContext.ToString(),
                 e => e.ParentTarget,
                 e => e.Importance.ToString(),
                 e => e.LineNumber.ToString(),
                 e => e.ColumnNumber.ToString(),
-                e => e.LineNumber.ToString(),
                 e => e.Message,
                 e => e.ProjectFile,
                 e => e.TargetFile,
                 e => e.TargetName,
-                e => e.BuildReason.ToString());
+                e => e.BuildReason.ToString(),
+                e => e.SkipReason.ToString(),
+                e => e.Condition,
+                e => e.EvaluatedCondition,
+                e => e.OriginalBuildEventContext.ToString(),
+                e => e.OriginallySucceeded.ToString());
         }
 
         [Fact]

src/Build/BackEnd/Components/Communications/TranslatorExtensions.cs

@@ -4,10 +4,11 @@
 using System;
 using System.Collections.Concurrent;
 using System.Linq;
+using System.Reflection;
 using Microsoft.Build.Collections;
 using Microsoft.Build.Execution;
+using Microsoft.Build.Framework;
 using Microsoft.Build.Shared;
-using System.Reflection;
 
 namespace Microsoft.Build.BackEnd
 {
@@ -103,5 +104,17 @@ public static T FactoryForDeserializingTypeWithName<T>(this ITranslator translat
 
             return (T) targetInstanceChild;
         }
+
+        public static void TranslateOptionalBuildEventContext(this ITranslator translator, ref BuildEventContext buildEventContext)
+        {
+            if (translator.Mode == TranslationDirection.ReadFromStream)
+            {
+                buildEventContext = translator.Reader.ReadOptionalBuildEventContext();
+            }
+            else
+            {
+                translator.Writer.WriteOptionalBuildEventContext(buildEventContext);
+            }
+        }
     }
 }

src/Build/BackEnd/Components/Logging/NodeLoggingContext.cs

@@ -86,18 +86,26 @@ internal void LogRequestHandledFromCache(BuildRequest request, BuildRequestConfi
         {
             ProjectLoggingContext projectLoggingContext = LogProjectStarted(request, configuration);
 
-            // When pulling a request from the cache, we want to make sure we log a task skipped message for any targets which 
-            // were used to build the request including default and inital targets.
+            // When pulling a request from the cache, we want to make sure we log a target skipped event for any targets which
+            // were used to build the request including default and initial targets.
             foreach (string target in configuration.GetTargetsUsedToBuildRequest(request))
             {
-                projectLoggingContext.LogComment
-                    (
-                        MessageImportance.Low,
-                        result[target].ResultCode == TargetResultCode.Failure ? "TargetAlreadyCompleteFailure" : "TargetAlreadyCompleteSuccess",
-                        target
-                    );
-
-                if (result[target].ResultCode == TargetResultCode.Failure)
+                var targetResult = result[target];
+                bool isFailure = targetResult.ResultCode == TargetResultCode.Failure;
+
+                var skippedTargetEventArgs = new TargetSkippedEventArgs(message: null)
+                {
+                    BuildEventContext = projectLoggingContext.BuildEventContext,
+                    TargetName = target,
+                    BuildReason = TargetBuiltReason.None,
+                    SkipReason = isFailure ? TargetSkipReason.PreviouslyBuiltUnsuccessfully : TargetSkipReason.PreviouslyBuiltSuccessfully,
+                    OriginallySucceeded = !isFailure,
+                    OriginalBuildEventContext = (targetResult as TargetResult)?.OriginalBuildEventContext
+                };
+
+                projectLoggingContext.LogBuildEvent(skippedTargetEventArgs);
+
+                if (targetResult.ResultCode == TargetResultCode.Failure)
                 {
                     break;
                 }

src/Build/BackEnd/Components/RequestBuilder/TargetBuilder.cs

@@ -555,14 +555,17 @@ private bool CheckSkipTarget(ref bool stopProcessingStack, TargetEntry currentTa
                 {
                     // If we've already dealt with this target and it didn't skip, let's log appropriately
                     // Otherwise we don't want anything more to do with it.
+                    bool success = targetResult.ResultCode == TargetResultCode.Success;
                     var skippedTargetEventArgs = new TargetSkippedEventArgs(message: null)
                     {
                         BuildEventContext = _projectLoggingContext.BuildEventContext,
                         TargetName = currentTargetEntry.Name,
                         TargetFile = currentTargetEntry.Target.Location.File,
                         ParentTarget = currentTargetEntry.ParentEntry?.Target.Name,
                         BuildReason = currentTargetEntry.BuildReason,
-                        OriginallySucceeded = targetResult.ResultCode == TargetResultCode.Success
+                        OriginallySucceeded = success,
+                        SkipReason = success ? TargetSkipReason.PreviouslyBuiltSuccessfully : TargetSkipReason.PreviouslyBuiltUnsuccessfully,
+                        OriginalBuildEventContext = targetResult.OriginalBuildEventContext
                     };
 
                     _projectLoggingContext.LogBuildEvent(skippedTargetEventArgs);

src/Build/BackEnd/Components/RequestBuilder/TargetEntry.cs

@@ -354,7 +354,10 @@ internal List<TargetSpecification> GetDependencies(ProjectLoggingContext project
 
             if (!condition)
             {
-                _targetResult = new TargetResult(Array.Empty<TaskItem>(), new WorkUnitResult(WorkUnitResultCode.Skipped, WorkUnitActionCode.Continue, null));
+                _targetResult = new TargetResult(
+                    Array.Empty<TaskItem>(),
+                    new WorkUnitResult(WorkUnitResultCode.Skipped, WorkUnitActionCode.Continue, null),
+                    projectLoggingContext.BuildEventContext);
                 _state = TargetEntryState.Completed;
 
                 if (!projectLoggingContext.LoggingService.OnlyLogCriticalEvents)
@@ -375,6 +378,7 @@ internal List<TargetSpecification> GetDependencies(ProjectLoggingContext project
                         TargetFile = _target.Location.File,
                         ParentTarget = ParentEntry?.Target?.Name,
                         BuildReason = BuildReason,
+                        SkipReason = TargetSkipReason.ConditionWasFalse,
                         Condition = _target.Condition,
                         EvaluatedCondition = expanded
                     };
@@ -640,14 +644,11 @@ internal async Task ExecuteTarget(ITaskBuilder taskBuilder, BuildRequestEntry re
                 }
                 finally
                 {
-
-
-                        // log the last target finished since we now have the target outputs. 
-                        targetLoggingContext?.LogTargetBatchFinished(projectFullPath, targetSuccess, targetOutputItems?.Count > 0 ? targetOutputItems : null);
-
+                    // log the last target finished since we now have the target outputs. 
+                    targetLoggingContext?.LogTargetBatchFinished(projectFullPath, targetSuccess, targetOutputItems?.Count > 0 ? targetOutputItems : null);
                 }
 
-                _targetResult = new TargetResult(targetOutputItems.ToArray(), aggregateResult);
+                _targetResult = new TargetResult(targetOutputItems.ToArray(), aggregateResult, targetLoggingContext?.BuildEventContext);
 
                 if (aggregateResult.ResultCode == WorkUnitResultCode.Failed && aggregateResult.ActionCode == WorkUnitActionCode.Stop)
                 {

src/Build/BackEnd/Components/RequestBuilder/TargetUpToDateChecker.cs

@@ -233,9 +233,17 @@ out ItemDictionary<ProjectItemInstance> upToDateTargetInputs
 
                 if (result == DependencyAnalysisResult.SkipUpToDate)
                 {
-                    _loggingService.LogComment(_buildEventContext, MessageImportance.Normal,
-                        "SkipTargetBecauseOutputsUpToDate",
-                        TargetToAnalyze.Name);
+                    var skippedTargetEventArgs = new TargetSkippedEventArgs(message: null)
+                    {
+                        BuildEventContext = _buildEventContext,
+                        TargetName = TargetToAnalyze.Name,
+                        BuildReason = TargetBuiltReason.None,
+                        SkipReason = TargetSkipReason.OutputsUpToDate,
+                        OriginallySucceeded = true,
+                        Importance = MessageImportance.Normal
+                    };
+
+                    _loggingService.LogBuildEvent(skippedTargetEventArgs);
 
                     // Log the target inputs & outputs
                     if (!_loggingService.OnlyLogCriticalEvents)
@@ -337,7 +345,7 @@ private static string GetIncrementalBuildReason(DependencyAnalysisLogDetail logD
 
         /// <summary>
         /// Extract only the unique inputs and outputs from all the inputs and outputs gathered
-        /// during depedency analysis
+        /// during dependency analysis
         /// </summary>
         private void LogUniqueInputsAndOutputs()
         {