Add better step telemetry and tracing for composite Actions (#1229)

* Add Step Telemetry

* better telemetry and tracing

* cleanup

src/Runner.Worker/ExecutionContext.cs

@@ -50,6 +50,7 @@ namespace GitHub.Runner.Worker
         Dictionary<string, string> IntraActionState { get; }
         Dictionary<string, VariableValue> JobOutputs { get; }
         ActionsEnvironmentReference ActionsEnvironment { get; }
+        List<ActionsStepTelemetry> ActionsStepsTelemetry { get; }
         DictionaryContextData ExpressionValues { get; }
         IList<IFunctionInfo> ExpressionFunctions { get; }
         JobContext JobContext { get; }
@@ -146,6 +147,7 @@ namespace GitHub.Runner.Worker
         public Dictionary<string, VariableValue> JobOutputs { get; private set; }
 
         public ActionsEnvironmentReference ActionsEnvironment { get; private set; }
+        public List<ActionsStepTelemetry> ActionsStepsTelemetry { get; private set; }
         public DictionaryContextData ExpressionValues { get; } = new DictionaryContextData();
         public IList<IFunctionInfo> ExpressionFunctions { get; } = new List<IFunctionInfo>();
 
@@ -637,6 +639,9 @@ namespace GitHub.Runner.Worker
             // Actions environment
             ActionsEnvironment = message.ActionsEnvironment;
 
+            // ActionsStepTelemetry
+            ActionsStepsTelemetry = new List<ActionsStepTelemetry>();
+
             // Service container info
             Global.ServiceContainers = new List<ContainerInfo>();
 
@@ -967,6 +972,18 @@ namespace GitHub.Runner.Worker
             context.Write(null, message);
         }
 
+        public static void WriteDetails(this IExecutionContext context, string message)
+        {
+            if (context.IsEmbedded)
+            {
+                context.Debug(message);
+            }
+            else
+            {
+                context.Output(message);
+            }
+        }
+
         // Do not add a format string overload. See comment on ExecutionContext.Write().
         public static void Command(this IExecutionContext context, string message)
         {

src/Runner.Worker/Handlers/CompositeActionHandler.cs

@@ -61,6 +61,36 @@ namespace GitHub.Runner.Worker.Handlers
                 steps = Data.Steps;
             }
 
+            // Add Telemetry to JobContext to send with JobCompleteMessage
+            if (stage == ActionRunStage.Main)
+            {
+                var hasRunsStep = false;
+                var hasUsesStep = false;
+                foreach (var step in steps)
+                {
+                    if (step.Reference.Type == Pipelines.ActionSourceType.Script)
+                    {
+                        hasRunsStep = true;
+                    }
+                    else
+                    {
+                        hasUsesStep = true;
+                    }
+                }
+                var pathReference = Action as Pipelines.RepositoryPathReference;
+                var telemetry = new ActionsStepTelemetry {
+                    Ref = GetActionRef(),
+                    HasPreStep = Data.HasPre,
+                    HasPostStep = Data.HasPost,
+                    IsEmbedded = ExecutionContext.IsEmbedded,
+                    Type = "composite",
+                    HasRunsStep = hasRunsStep,
+                    HasUsesStep = hasUsesStep,
+                    StepCount = steps.Count
+                };
+                ExecutionContext.Root.ActionsStepsTelemetry.Add(telemetry);
+            }
+            
             try
             {
                 // Inputs of the composite step

src/Runner.Worker/Handlers/ContainerActionHandler.cs

@@ -50,8 +50,8 @@ namespace GitHub.Runner.Worker.Handlers
                 var dockerFile = Path.Combine(ActionDirectory, Data.Image);
                 ArgUtil.File(dockerFile, nameof(Data.Image));
 
-                ExecutionContext.Output($"##[group]Building docker image");
+                ExecutionContext.WriteDetails(ExecutionContext.IsEmbedded ? "Building docker image" : $"##[group]Building docker image");
-                ExecutionContext.Output($"Dockerfile for action: '{dockerFile}'.");
+                ExecutionContext.WriteDetails($"Dockerfile for action: '{dockerFile}'.");
                 var imageName = $"{dockerManager.DockerInstanceLabel}:{ExecutionContext.Id.ToString("N")}";
                 var buildExitCode = await dockerManager.DockerBuild(
                     ExecutionContext,
@@ -59,7 +59,7 @@ namespace GitHub.Runner.Worker.Handlers
                     dockerFile,
                     Directory.GetParent(dockerFile).FullName,
                     imageName);
-                ExecutionContext.Output("##[endgroup]");
+                ExecutionContext.WriteDetails(ExecutionContext.IsEmbedded ? "" : "##[endgroup]");
 
                 if (buildExitCode != 0)
                 {
@@ -69,6 +69,20 @@ namespace GitHub.Runner.Worker.Handlers
                 Data.Image = imageName;
             }
 
+            string type = Action.Type == Pipelines.ActionSourceType.Repository ? "Dockerfile" : "DockerHub";
+            // Add Telemetry to JobContext to send with JobCompleteMessage
+            if (stage == ActionRunStage.Main)
+            {
+                var telemetry = new ActionsStepTelemetry {
+                    Ref = GetActionRef(),
+                    HasPreStep = Data.HasPre,
+                    HasPostStep = Data.HasPost,
+                    IsEmbedded = ExecutionContext.IsEmbedded,
+                    Type = type
+                };
+                ExecutionContext.Root.ActionsStepsTelemetry.Add(telemetry);
+            }
+
             // run container
             var container = new ContainerInfo(HostContext)
             {

src/Runner.Worker/Handlers/Handler.cs

@@ -44,11 +44,45 @@ namespace GitHub.Runner.Worker.Handlers
         public string ActionDirectory { get; set; }
         public List<JobExtensionRunner> LocalActionContainerSetupSteps { get; set; }
 
+        public virtual string GetActionRef()
+        {
+            if (Action.Type == Pipelines.ActionSourceType.ContainerRegistry)
+            {
+                var registryAction = Action as Pipelines.ContainerRegistryReference;
+                return registryAction.Image;
+            }
+            else if (Action.Type == Pipelines.ActionSourceType.Repository)
+            {
+                var repoAction = Action as Pipelines.RepositoryPathReference;
+                if (string.Equals(repoAction.RepositoryType, Pipelines.PipelineConstants.SelfAlias, StringComparison.OrdinalIgnoreCase))
+                {
+                    return repoAction.Path;
+                }
+                else
+                {
+                    if (string.IsNullOrEmpty(repoAction.Path))
+                    {
+                        return $"{repoAction.Name}@{repoAction.Ref}";
+                    }
+                    else
+                    {
+                        return $"{repoAction.Name}/{repoAction.Path}@{repoAction.Ref}";
+                    }
+                }
+            }
+            else
+            {
+                // this should never happen
+                Trace.Error($"Can't generate ref for {Action.Type.ToString()}");
+            }
+            return "";
+        }
         public virtual void PrintActionDetails(ActionRunStage stage)
         {
+            
             if (stage == ActionRunStage.Post)
             {
-                ExecutionContext.Output($"Post job cleanup.");
+                ExecutionContext.WriteDetails($"Post job cleanup.");
                 return;
             }
 
@@ -84,30 +118,30 @@ namespace GitHub.Runner.Worker.Handlers
                 groupName = "Action details";
             }
 
-            ExecutionContext.Output($"##[group]{groupName}");
+            ExecutionContext.WriteDetails(ExecutionContext.IsEmbedded ? groupName : $"##[group]{groupName}");
 
             if (this.Inputs?.Count > 0)
             {
-                ExecutionContext.Output("with:");
+                ExecutionContext.WriteDetails("with:");
                 foreach (var input in this.Inputs)
                 {
                     if (!string.IsNullOrEmpty(input.Value))
                     {
-                        ExecutionContext.Output($"  {input.Key}: {input.Value}");
+                        ExecutionContext.WriteDetails($"  {input.Key}: {input.Value}");
                     }
                 }
             }
 
             if (this.Environment?.Count > 0)
             {
-                ExecutionContext.Output("env:");
+                ExecutionContext.WriteDetails("env:");
                 foreach (var env in this.Environment)
                 {
-                    ExecutionContext.Output($"  {env.Key}: {env.Value}");
+                    ExecutionContext.WriteDetails($"  {env.Key}: {env.Value}");
                 }
             }
 
-            ExecutionContext.Output("##[endgroup]");
+            ExecutionContext.WriteDetails(ExecutionContext.IsEmbedded ? "" : "##[endgroup]");
         }
 
         public override void Initialize(IHostContext hostContext)

src/Runner.Worker/Handlers/NodeScriptActionHandler.cs

@@ -69,6 +69,19 @@ namespace GitHub.Runner.Worker.Handlers
                 target = Data.Post;
             }
 
+            // Add Telemetry to JobContext to send with JobCompleteMessage
+            if (stage == ActionRunStage.Main)
+            {
+                var telemetry = new ActionsStepTelemetry {
+                    Ref = GetActionRef(),
+                    HasPreStep = Data.HasPre,
+                    HasPostStep = Data.HasPost,
+                    IsEmbedded = ExecutionContext.IsEmbedded,
+                    Type = "node12"
+                };
+                ExecutionContext.Root.ActionsStepsTelemetry.Add(telemetry);
+            }
+
             ArgUtil.NotNullOrEmpty(target, nameof(target));
             target = Path.Combine(ActionDirectory, target);
             ArgUtil.File(target, nameof(target));

src/Runner.Worker/Handlers/ScriptHandler.cs

@@ -23,18 +23,6 @@ namespace GitHub.Runner.Worker.Handlers
 
         public override void PrintActionDetails(ActionRunStage stage)
         {
-            // We don't want to display the internal workings if composite (similar/equivalent information can be found in debug)
-            void writeDetails(string message)
-            {
-                if (ExecutionContext.IsEmbedded)
-                {
-                    ExecutionContext.Debug(message);
-                }
-                else
-                {
-                    ExecutionContext.Output(message);
-                }
-            }
 
             if (stage == ActionRunStage.Post)
             {
@@ -52,7 +40,7 @@ namespace GitHub.Runner.Worker.Handlers
                     firstLine = firstLine.Substring(0, firstNewLine);
                 }
 
-                writeDetails(ExecutionContext.IsEmbedded ? $"Run {firstLine}" : $"##[group]Run {firstLine}");
+                ExecutionContext.WriteDetails(ExecutionContext.IsEmbedded ? $"Run {firstLine}" : $"##[group]Run {firstLine}");
             }
             else
             {
@@ -63,7 +51,7 @@ namespace GitHub.Runner.Worker.Handlers
             foreach (var line in multiLines)
             {
                 // Bright Cyan color
-                writeDetails($"\x1b[36;1m{line}\x1b[0m");
+                ExecutionContext.WriteDetails($"\x1b[36;1m{line}\x1b[0m");
             }
 
             string argFormat;
@@ -122,23 +110,23 @@ namespace GitHub.Runner.Worker.Handlers
 
             if (!string.IsNullOrEmpty(shellCommandPath))
             {
-                writeDetails($"shell: {shellCommandPath} {argFormat}");
+                ExecutionContext.WriteDetails($"shell: {shellCommandPath} {argFormat}");
             }
             else
             {
-                writeDetails($"shell: {shellCommand} {argFormat}");
+                ExecutionContext.WriteDetails($"shell: {shellCommand} {argFormat}");
             }
 
             if (this.Environment?.Count > 0)
             {
-                writeDetails("env:");
+                ExecutionContext.WriteDetails("env:");
                 foreach (var env in this.Environment)
                 {
-                    writeDetails($"  {env.Key}: {env.Value}");
+                    ExecutionContext.WriteDetails($"  {env.Key}: {env.Value}");
                 }
             }
 
-            writeDetails(ExecutionContext.IsEmbedded ? "" : "##[endgroup]");
+            ExecutionContext.WriteDetails(ExecutionContext.IsEmbedded ? "" : "##[endgroup]");
         }
 
         public async Task RunAsync(ActionRunStage stage)
@@ -156,6 +144,16 @@ namespace GitHub.Runner.Worker.Handlers
             var githubContext = ExecutionContext.ExpressionValues["github"] as GitHubContext;
             ArgUtil.NotNull(githubContext, nameof(githubContext));
 
+            // Add Telemetry to JobContext to send with JobCompleteMessage
+            if (stage == ActionRunStage.Main)
+            {
+                var telemetry = new ActionsStepTelemetry {
+                    IsEmbedded = ExecutionContext.IsEmbedded,
+                    Type = "run",
+                };
+                ExecutionContext.Root.ActionsStepsTelemetry.Add(telemetry);
+            }
+
             var tempDirectory = HostContext.GetDirectory(WellKnownDirectory.Temp);
 
             Inputs.TryGetValue("script", out var contents);

src/Runner.Worker/JobRunner.cs

@@ -216,7 +216,7 @@ namespace GitHub.Runner.Worker
             }
 
             Trace.Info("Raising job completed event.");
-            var jobCompletedEvent = new JobCompletedEvent(message.RequestId, message.JobId, result, jobContext.JobOutputs, jobContext.ActionsEnvironment);
+            var jobCompletedEvent = new JobCompletedEvent(message.RequestId, message.JobId, result, jobContext.JobOutputs, jobContext.ActionsEnvironment, jobContext.ActionsStepsTelemetry);
 
             var completeJobRetryLimit = 5;
             var exceptions = new List<Exception>();

src/Sdk/DTWebApi/WebApi/ActionsStepTelemetry.cs

@@ -0,0 +1,36 @@
+using System.Runtime.Serialization;
+
+namespace GitHub.DistributedTask.WebApi
+{
+    /// <summary>
+    /// Information about a step run on the runner
+    /// </summary>
+    [DataContract]
+    public class ActionsStepTelemetry
+    {
+
+        [DataMember(EmitDefaultValue = false)]
+        public string Ref { get; set; }
+
+        [DataMember(EmitDefaultValue = false)]
+        public string Type { get; set; }
+
+        [DataMember(EmitDefaultValue = false)]
+        public bool? HasRunsStep { get; set; }
+                
+        [DataMember(EmitDefaultValue = false)]
+        public bool? HasUsesStep { get; set; }
+
+        [DataMember(EmitDefaultValue = false)]
+        public bool IsEmbedded { get; set; }
+
+        [DataMember(EmitDefaultValue = false)]
+        public bool? HasPreStep { get; set; }
+
+        [DataMember(EmitDefaultValue = false)]
+        public bool? HasPostStep { get; set; }
+
+        [DataMember(EmitDefaultValue = false)]
+        public int? StepCount { get; set; }
+    }
+}

src/Sdk/DTWebApi/WebApi/JobEvent.cs

@@ -142,6 +142,19 @@ namespace GitHub.DistributedTask.WebApi
             this.ActionsEnvironment = actionsEnvironment;
         }
 
+        public JobCompletedEvent(
+            Int64 requestId,
+            Guid jobId,
+            TaskResult result,
+            Dictionary<String, VariableValue> outputs,
+            ActionsEnvironmentReference actionsEnvironment,
+            List<ActionsStepTelemetry> actionsStepsTelemetry)
+            : this(requestId, jobId, result, outputs)
+        {
+            this.ActionsEnvironment = actionsEnvironment;
+            this.ActionsStepsTelemetry = actionsStepsTelemetry;
+        }
+
         [DataMember(EmitDefaultValue = false)]
         public Int64 RequestId
         {
@@ -169,6 +182,13 @@ namespace GitHub.DistributedTask.WebApi
             get;
             set;
         }
+
+        [DataMember(EmitDefaultValue = false)]
+        public List<ActionsStepTelemetry> ActionsStepsTelemetry
+        {
+            get;
+            set;
+        }
     }
 
     [DataContract]