Sending telemetry about actions usage. (actions#1688)

* Sending telemetry about actions usage.

* .

* L0 tests.

* .

src/Runner.Worker/ActionRunner.cs

@@ -1,4 +1,5 @@
 using System;
+using System.Collections.Generic;
 using System.IO;
 using System.Text;
 using System.Threading.Tasks;
@@ -7,12 +8,11 @@
 using GitHub.DistributedTask.Pipelines;
 using GitHub.DistributedTask.Pipelines.ContextData;
 using GitHub.DistributedTask.Pipelines.ObjectTemplating;
+using GitHub.Runner.Common;
 using GitHub.Runner.Common.Util;
+using GitHub.Runner.Sdk;
 using GitHub.Runner.Worker.Handlers;
 using Pipelines = GitHub.DistributedTask.Pipelines;
-using GitHub.Runner.Common;
-using GitHub.Runner.Sdk;
-using System.Collections.Generic;
 
 namespace GitHub.Runner.Worker
 {
@@ -274,8 +274,8 @@ Action.Reference is Pipelines.RepositoryPathReference repoAction &&
                             actionDirectory: definition.Directory,
                             localActionContainerSetupSteps: localActionContainerSetupSteps);
 
-            // Print out action details
-            handler.PrintActionDetails(Stage);
+            // Print out action details and log telemetry
+            handler.PrepareExecution(Stage);
 
             // Run the task.
             try

src/Runner.Worker/ExecutionContext.cs

@@ -115,6 +115,9 @@ public sealed class ExecutionContext : RunnerService, IExecutionContext
     {
         private const int _maxIssueCount = 10;
         private const int _throttlingDelayReportThreshold = 10 * 1000; // Don't report throttling with less than 10 seconds delay
+        private const int _maxIssueMessageLength = 4096; // Don't send issue with huge message since we can't forward them from actions to check annotation.
+        private const int _maxIssueCountInTelemetry = 3; // Only send the first 3 issues to telemetry
+        private const int _maxIssueMessageLengthInTelemetry = 256; // Only send the first 256 characters of issue message to telemetry
 
         private readonly TimelineRecord _record = new TimelineRecord();
         private readonly Dictionary<Guid, TimelineRecord> _detailRecords = new Dictionary<Guid, TimelineRecord>();
@@ -358,6 +361,9 @@ public IExecutionContext CreateChild(
             }
 
             child.IsEmbedded = isEmbedded;
+            child.StepTelemetry.StepId = recordId;
+            child.StepTelemetry.Stage = stage.ToString();
+            child.StepTelemetry.IsEmbedded = isEmbedded;
 
             return child;
         }
@@ -539,6 +545,10 @@ public void AddIssue(Issue issue, string logMessage = null)
             }
 
             issue.Message = HostContext.SecretMasker.MaskSecrets(issue.Message);
+            if (issue.Message.Length > _maxIssueMessageLength)
+            {
+                issue.Message = issue.Message[.._maxIssueMessageLength];
+            }
 
             if (issue.Type == IssueType.Error)
             {
@@ -929,6 +939,47 @@ public void PublishStepTelemetry()
                 // Add to the global steps telemetry only if we have something to log.
                 if (!string.IsNullOrEmpty(StepTelemetry?.Type))
                 {
+                    if (!IsEmbedded)
+                    {
+                        StepTelemetry.Result = _record.Result;
+                    }
+
+                    if (!IsEmbedded &&
+                        _record.FinishTime != null &&
+                        _record.StartTime != null)
+                    {
+                        StepTelemetry.ExecutionTimeInSeconds = (int)Math.Ceiling((_record.FinishTime - _record.StartTime)?.TotalSeconds ?? 0);
+                    }
+
+                    if (!IsEmbedded &&
+                        _record.Issues.Count > 0)
+                    {
+                        foreach (var issue in _record.Issues)
+                        {
+                            if ((issue.Type == IssueType.Error || issue.Type == IssueType.Warning) &&
+                                !string.IsNullOrEmpty(issue.Message))
+                            {
+                                string issueTelemetry;
+                                if (issue.Message.Length > _maxIssueMessageLengthInTelemetry)
+                                {
+                                    issueTelemetry = $"{issue.Message[.._maxIssueMessageLengthInTelemetry]}";
+                                }
+                                else
+                                {
+                                    issueTelemetry = issue.Message;
+                                }
+
+                                StepTelemetry.ErrorMessages.Add(issueTelemetry);
+
+                                // Only send over the first 3 issues to avoid sending too much data.
+                                if (StepTelemetry.ErrorMessages.Count >= _maxIssueCountInTelemetry)
+                                {
+                                    break;
+                                }
+                            }
+                        }
+                    }
+
                     Trace.Info($"Publish step telemetry for current step {StringUtil.ConvertToJson(StepTelemetry)}.");
                     Global.StepsTelemetry.Add(StepTelemetry);
                     _stepTelemetryPublished = true;

src/Runner.Worker/Handlers/CompositeActionHandler.cs

@@ -67,7 +67,7 @@ public async Task RunAsync(ActionRunStage stage)
                 steps = Data.Steps;
             }
 
-            // Add Telemetry to JobContext to send with JobCompleteMessage
+            // Set extra telemetry base on the current context.
             if (stage == ActionRunStage.Main)
             {
                 var hasRunsStep = false;
@@ -84,15 +84,14 @@ public async Task RunAsync(ActionRunStage stage)
                     }
                 }
 
-                ExecutionContext.StepTelemetry.Ref = GetActionRef();
                 ExecutionContext.StepTelemetry.HasPreStep = Data.HasPre;
                 ExecutionContext.StepTelemetry.HasPostStep = Data.HasPost;
-                ExecutionContext.StepTelemetry.IsEmbedded = ExecutionContext.IsEmbedded;
-                ExecutionContext.StepTelemetry.Type = "composite";
+
                 ExecutionContext.StepTelemetry.HasRunsStep = hasRunsStep;
                 ExecutionContext.StepTelemetry.HasUsesStep = hasUsesStep;
                 ExecutionContext.StepTelemetry.StepCount = steps.Count;
             }
+            ExecutionContext.StepTelemetry.Type = "composite";
 
             try
             {

src/Runner.Worker/Handlers/ContainerActionHandler.cs

@@ -70,15 +70,13 @@ public async Task RunAsync(ActionRunStage stage)
             }
 
             string type = Action.Type == Pipelines.ActionSourceType.Repository ? "Dockerfile" : "DockerHub";
-            // Add Telemetry to JobContext to send with JobCompleteMessage
+            // Set extra telemetry base on the current context.
             if (stage == ActionRunStage.Main)
             {
-                ExecutionContext.StepTelemetry.Ref = GetActionRef();
                 ExecutionContext.StepTelemetry.HasPreStep = Data.HasPre;
                 ExecutionContext.StepTelemetry.HasPostStep = Data.HasPost;
-                ExecutionContext.StepTelemetry.IsEmbedded = ExecutionContext.IsEmbedded;
-                ExecutionContext.StepTelemetry.Type = type;
             }
+            ExecutionContext.StepTelemetry.Type = type;
 
             // run container
             var container = new ContainerInfo(HostContext)

src/Runner.Worker/Handlers/Handler.cs

@@ -22,7 +22,7 @@ public interface IHandler : IRunnerService
         string ActionDirectory { get; set; }
         List<JobExtensionRunner> LocalActionContainerSetupSteps { get; set; }
         Task RunAsync(ActionRunStage stage);
-        void PrintActionDetails(ActionRunStage stage);
+        void PrepareExecution(ActionRunStage stage);
     }
 
     public abstract class Handler : RunnerService
@@ -44,8 +44,56 @@ public abstract class Handler : RunnerService
         public string ActionDirectory { get; set; }
         public List<JobExtensionRunner> LocalActionContainerSetupSteps { get; set; }
 
+        public void PrepareExecution(ActionRunStage stage)
+        {
+            // Print out action details
+            PrintActionDetails(stage);
+
+            // Get telemetry for the action.
+            PopulateActionTelemetry();
+        }
 
-        public virtual void PrintActionDetails(ActionRunStage stage)
+        protected void PopulateActionTelemetry()
+        {
+            if (Action.Type == Pipelines.ActionSourceType.ContainerRegistry)
+            {
+                ExecutionContext.StepTelemetry.Type = "docker";
+                var registryAction = Action as Pipelines.ContainerRegistryReference;
+                ExecutionContext.StepTelemetry.Action = registryAction.Image;
+            }
+            else if (Action.Type == Pipelines.ActionSourceType.Script)
+            {
+                ExecutionContext.StepTelemetry.Type = "run";
+            }
+            else if (Action.Type == Pipelines.ActionSourceType.Repository)
+            {
+                ExecutionContext.StepTelemetry.Type = "repository";
+                var repoAction = Action as Pipelines.RepositoryPathReference;
+                if (string.Equals(repoAction.RepositoryType, Pipelines.PipelineConstants.SelfAlias, StringComparison.OrdinalIgnoreCase))
+                {
+                    ExecutionContext.StepTelemetry.Action = repoAction.Path;
+                }
+                else
+                {
+                    ExecutionContext.StepTelemetry.Ref = repoAction.Ref;
+                    if (string.IsNullOrEmpty(repoAction.Path))
+                    {
+                        ExecutionContext.StepTelemetry.Action = repoAction.Name;
+                    }
+                    else
+                    {
+                        ExecutionContext.StepTelemetry.Action = $"{repoAction.Name}/{repoAction.Path}";
+                    }
+                }
+            }
+            else
+            {
+                // this should never happen
+                Trace.Error($"Can't generate ref for {Action.Type.ToString()}");
+            }
+        }
+
+        protected virtual void PrintActionDetails(ActionRunStage stage)
         {
 
             if (stage == ActionRunStage.Post)
@@ -118,40 +166,6 @@ public override void Initialize(IHostContext hostContext)
             ActionCommandManager = hostContext.CreateService<IActionCommandManager>();
         }
 
-        protected 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 "";
-        }
-
         protected void AddInputsToEnvironment()
         {
             // Validate args.

src/Runner.Worker/Handlers/NodeScriptActionHandler.cs

@@ -74,15 +74,13 @@ public async Task RunAsync(ActionRunStage stage)
                 target = Data.Post;
             }
 
-            // Add Telemetry to JobContext to send with JobCompleteMessage
+            // Set extra telemetry base on the current context.
             if (stage == ActionRunStage.Main)
             {
-                ExecutionContext.StepTelemetry.Ref = GetActionRef();
                 ExecutionContext.StepTelemetry.HasPreStep = Data.HasPre;
                 ExecutionContext.StepTelemetry.HasPostStep = Data.HasPost;
-                ExecutionContext.StepTelemetry.IsEmbedded = ExecutionContext.IsEmbedded;
-                ExecutionContext.StepTelemetry.Type = Data.NodeVersion;
             }
+            ExecutionContext.StepTelemetry.Type = Data.NodeVersion;
 
             ArgUtil.NotNullOrEmpty(target, nameof(target));
             target = Path.Combine(ActionDirectory, target);

src/Runner.Worker/Handlers/RunnerPluginHandler.cs

@@ -1,7 +1,7 @@
-using System.Threading.Tasks;
-using System;
-using GitHub.Runner.Sdk;
+using System;
+using System.Threading.Tasks;
 using GitHub.Runner.Common;
+using GitHub.Runner.Sdk;
 using Pipelines = GitHub.DistributedTask.Pipelines;
 
 namespace GitHub.Runner.Worker.Handlers
@@ -35,6 +35,8 @@ public async Task RunAsync(ActionRunStage stage)
             }
 
             ArgUtil.NotNullOrEmpty(plugin, nameof(plugin));
+            // Set extra telemetry base on the current context.
+            ExecutionContext.StepTelemetry.Type = plugin;
 
             // Update the env dictionary.
             AddPrependPathToEnvironment();

src/Runner.Worker/Handlers/ScriptHandler.cs

@@ -22,7 +22,7 @@ public sealed class ScriptHandler : Handler, IScriptHandler
     {
         public ScriptActionExecutionData Data { get; set; }
 
-        public override void PrintActionDetails(ActionRunStage stage)
+        protected override void PrintActionDetails(ActionRunStage stage)
         {
 
             if (stage == ActionRunStage.Post)
@@ -145,13 +145,6 @@ public async Task RunAsync(ActionRunStage stage)
             var githubContext = ExecutionContext.ExpressionValues["github"] as GitHubContext;
             ArgUtil.NotNull(githubContext, nameof(githubContext));
 
-            // Add Telemetry to JobContext to send with JobCompleteMessage
-            if (stage == ActionRunStage.Main)
-            {
-                ExecutionContext.StepTelemetry.IsEmbedded = ExecutionContext.IsEmbedded;
-                ExecutionContext.StepTelemetry.Type = "run";
-            }
-
             var tempDirectory = HostContext.GetDirectory(WellKnownDirectory.Temp);
 
             Inputs.TryGetValue("script", out var contents);
@@ -219,6 +212,11 @@ public async Task RunAsync(ActionRunStage stage)
                 }
             }
 
+            if (!string.IsNullOrEmpty(shellCommand))
+            {
+                ExecutionContext.StepTelemetry.Action = shellCommand;
+            }
+
             // No arg format was given, shell must be a built-in
             if (string.IsNullOrEmpty(argFormat) || !argFormat.Contains("{0}"))
             {

src/Runner.Worker/JobExtension.cs

@@ -56,6 +56,8 @@ public async Task<List<IStep>> InitializeJob(IExecutionContext jobContext, Pipel
 
             // Create a new timeline record for 'Set up job'
             IExecutionContext context = jobContext.CreateChild(Guid.NewGuid(), "Set up job", $"{nameof(JobExtension)}_Init", null, null, ActionRunStage.Pre);
+            context.StepTelemetry.Type = "runner";
+            context.StepTelemetry.Action = "setup_job";
 
             List<IStep> preJobSteps = new List<IStep>();
             List<IStep> jobSteps = new List<IStep>();
@@ -313,6 +315,8 @@ public async Task<List<IStep>> InitializeJob(IExecutionContext jobContext, Pipel
                             ArgUtil.NotNull(extensionStep, extensionStep.DisplayName);
                             Guid stepId = Guid.NewGuid();
                             extensionStep.ExecutionContext = jobContext.CreateChild(stepId, extensionStep.DisplayName, stepId.ToString("N"), null, stepId.ToString("N"), ActionRunStage.Pre);
+                            extensionStep.ExecutionContext.StepTelemetry.Type = "runner";
+                            extensionStep.ExecutionContext.StepTelemetry.Action = extensionStep.DisplayName.ToLowerInvariant().Replace(' ', '_');
                         }
                         else if (step is IActionRunner actionStep)
                         {
@@ -401,6 +405,8 @@ public void FinalizeJob(IExecutionContext jobContext, Pipelines.AgentJobRequestM
 
             // create a new timeline record node for 'Finalize job'
             IExecutionContext context = jobContext.CreateChild(Guid.NewGuid(), "Complete job", $"{nameof(JobExtension)}_Final", null, null, ActionRunStage.Post);
+            context.StepTelemetry.Type = "runner";
+            context.StepTelemetry.Action = "complete_joh";
             using (var register = jobContext.CancellationToken.Register(() => { context.CancelToken(); }))
             {
                 try

src/Runner.Worker/JobRunner.cs

@@ -284,8 +284,8 @@ private async Task<TaskResult> CompleteJobAsync(IJobServer jobServer, IExecution
             // Make sure we don't submit secrets as telemetry
             MaskTelemetrySecrets(jobContext.Global.JobTelemetry);
 
+            Trace.Info($"Raising job completed event");
             var jobCompletedEvent = new JobCompletedEvent(message.RequestId, message.JobId, result, jobContext.JobOutputs, jobContext.ActionsEnvironment, jobContext.Global.StepsTelemetry, jobContext.Global.JobTelemetry);
-            Trace.Info($"Raising job completed event: {StringUtil.ConvertToJson(jobCompletedEvent)}");
 
             var completeJobRetryLimit = 5;
             var exceptions = new List<Exception>();