diff --git a/src/Runner.Worker/ActionRunner.cs b/src/Runner.Worker/ActionRunner.cs index 22c892480d5..afad9736ec7 100644 --- a/src/Runner.Worker/ActionRunner.cs +++ b/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 diff --git a/src/Runner.Worker/ExecutionContext.cs b/src/Runner.Worker/ExecutionContext.cs index b1ff5182b5b..a79f2b66d3e 100644 --- a/src/Runner.Worker/ExecutionContext.cs +++ b/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 _detailRecords = new Dictionary(); @@ -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; diff --git a/src/Runner.Worker/Handlers/CompositeActionHandler.cs b/src/Runner.Worker/Handlers/CompositeActionHandler.cs index 065a5fac8e9..45c9900fc34 100644 --- a/src/Runner.Worker/Handlers/CompositeActionHandler.cs +++ b/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 { diff --git a/src/Runner.Worker/Handlers/ContainerActionHandler.cs b/src/Runner.Worker/Handlers/ContainerActionHandler.cs index 6c13ee98160..3eaacb5a94c 100644 --- a/src/Runner.Worker/Handlers/ContainerActionHandler.cs +++ b/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) diff --git a/src/Runner.Worker/Handlers/Handler.cs b/src/Runner.Worker/Handlers/Handler.cs index 9290ad3a1a1..6bcc4987103 100644 --- a/src/Runner.Worker/Handlers/Handler.cs +++ b/src/Runner.Worker/Handlers/Handler.cs @@ -22,7 +22,7 @@ public interface IHandler : IRunnerService string ActionDirectory { get; set; } List 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 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(); } - 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. diff --git a/src/Runner.Worker/Handlers/NodeScriptActionHandler.cs b/src/Runner.Worker/Handlers/NodeScriptActionHandler.cs index 0b490e24cae..6887c27328f 100644 --- a/src/Runner.Worker/Handlers/NodeScriptActionHandler.cs +++ b/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); diff --git a/src/Runner.Worker/Handlers/RunnerPluginHandler.cs b/src/Runner.Worker/Handlers/RunnerPluginHandler.cs index 6b73b19f175..61949df1e9b 100644 --- a/src/Runner.Worker/Handlers/RunnerPluginHandler.cs +++ b/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(); diff --git a/src/Runner.Worker/Handlers/ScriptHandler.cs b/src/Runner.Worker/Handlers/ScriptHandler.cs index f75a10ce504..a5a71c97ec6 100644 --- a/src/Runner.Worker/Handlers/ScriptHandler.cs +++ b/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}")) { diff --git a/src/Runner.Worker/JobExtension.cs b/src/Runner.Worker/JobExtension.cs index 1115f4de1a1..ce0f37feef3 100644 --- a/src/Runner.Worker/JobExtension.cs +++ b/src/Runner.Worker/JobExtension.cs @@ -56,6 +56,8 @@ public async Task> 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 preJobSteps = new List(); List jobSteps = new List(); @@ -313,6 +315,8 @@ public async Task> 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 diff --git a/src/Runner.Worker/JobRunner.cs b/src/Runner.Worker/JobRunner.cs index 944931534d0..a4bba12acb9 100644 --- a/src/Runner.Worker/JobRunner.cs +++ b/src/Runner.Worker/JobRunner.cs @@ -284,8 +284,8 @@ private async Task 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(); diff --git a/src/Sdk/DTWebApi/WebApi/ActionsStepTelemetry.cs b/src/Sdk/DTWebApi/WebApi/ActionsStepTelemetry.cs index 8fdba317315..f46abe4c733 100644 --- a/src/Sdk/DTWebApi/WebApi/ActionsStepTelemetry.cs +++ b/src/Sdk/DTWebApi/WebApi/ActionsStepTelemetry.cs @@ -1,4 +1,6 @@ -using System.Runtime.Serialization; +using System; +using System.Collections.Generic; +using System.Runtime.Serialization; namespace GitHub.DistributedTask.WebApi { @@ -8,6 +10,13 @@ namespace GitHub.DistributedTask.WebApi [DataContract] public class ActionsStepTelemetry { + public ActionsStepTelemetry() + { + this.ErrorMessages = new List(); + } + + [DataMember(EmitDefaultValue = false)] + public string Action { get; set; } [DataMember(EmitDefaultValue = false)] public string Ref { get; set; } @@ -15,9 +24,15 @@ public class ActionsStepTelemetry [DataMember(EmitDefaultValue = false)] public string Type { get; set; } + [DataMember(EmitDefaultValue = false)] + public string Stage { get; set; } + + [DataMember(EmitDefaultValue = false)] + public Guid StepId { get; set; } + [DataMember(EmitDefaultValue = false)] public bool? HasRunsStep { get; set; } - + [DataMember(EmitDefaultValue = false)] public bool? HasUsesStep { get; set; } @@ -32,5 +47,14 @@ public class ActionsStepTelemetry [DataMember(EmitDefaultValue = false)] public int? StepCount { get; set; } + + [DataMember(EmitDefaultValue = false)] + public TaskResult? Result { get; set; } + + [DataMember(EmitDefaultValue = false)] + public List ErrorMessages { get; set; } + + [DataMember(EmitDefaultValue = false)] + public int? ExecutionTimeInSeconds { get; set; } } } diff --git a/src/Test/L0/Worker/ExecutionContextL0.cs b/src/Test/L0/Worker/ExecutionContextL0.cs index 170a1ef844c..e6351edb099 100644 --- a/src/Test/L0/Worker/ExecutionContextL0.cs +++ b/src/Test/L0/Worker/ExecutionContextL0.cs @@ -1,12 +1,12 @@ -using GitHub.DistributedTask.Pipelines.ContextData; -using GitHub.DistributedTask.WebApi; -using GitHub.Runner.Worker; -using Moq; -using System; +using System; using System.Collections.Generic; using System.Linq; using System.Runtime.CompilerServices; using System.Threading; +using GitHub.DistributedTask.Pipelines.ContextData; +using GitHub.DistributedTask.WebApi; +using GitHub.Runner.Worker; +using Moq; using Xunit; using Pipelines = GitHub.DistributedTask.Pipelines; @@ -90,6 +90,60 @@ public void AddIssue_CountWarningsErrors() } } + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void AddIssue_TrimMessageSize() + { + using (TestHostContext hc = CreateTestContext()) + { + // Arrange: Create a job request message. + TaskOrchestrationPlanReference plan = new TaskOrchestrationPlanReference(); + TimelineReference timeline = new TimelineReference(); + Guid jobId = Guid.NewGuid(); + string jobName = "some job name"; + var jobRequest = new Pipelines.AgentJobRequestMessage(plan, timeline, jobId, jobName, jobName, null, null, null, new Dictionary(), new List(), new Pipelines.JobResources(), new Pipelines.ContextData.DictionaryContextData(), new Pipelines.WorkspaceOptions(), new List(), null, null, null, null); + jobRequest.Resources.Repositories.Add(new Pipelines.RepositoryResource() + { + Alias = Pipelines.PipelineConstants.SelfAlias, + Id = "github", + Version = "sha1" + }); + jobRequest.ContextData["github"] = new Pipelines.ContextData.DictionaryContextData(); + + // Arrange: Setup the paging logger. + var pagingLogger = new Mock(); + var jobServerQueue = new Mock(); + jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); + + hc.EnqueueInstance(pagingLogger.Object); + hc.SetSingleton(jobServerQueue.Object); + + var ec = new Runner.Worker.ExecutionContext(); + ec.Initialize(hc); + + // Act. + ec.InitializeJob(jobRequest, CancellationToken.None); + + var bigMessage = ""; + for (var i = 0; i < 5000; i++) + { + bigMessage += "a"; + } + + ec.AddIssue(new Issue() { Type = IssueType.Error, Message = bigMessage }); + ec.AddIssue(new Issue() { Type = IssueType.Warning, Message = bigMessage }); + ec.AddIssue(new Issue() { Type = IssueType.Notice, Message = bigMessage }); + + ec.Complete(); + + // Assert. + jobServerQueue.Verify(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.Is(t => t.Issues.Where(i => i.Type == IssueType.Error).Single().Message.Length <= 4096)), Times.AtLeastOnce); + jobServerQueue.Verify(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.Is(t => t.Issues.Where(i => i.Type == IssueType.Warning).Single().Message.Length <= 4096)), Times.AtLeastOnce); + jobServerQueue.Verify(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.Is(t => t.Issues.Where(i => i.Type == IssueType.Notice).Single().Message.Length <= 4096)), Times.AtLeastOnce); + } + } + [Fact] [Trait("Level", "L0")] [Trait("Category", "Worker")] @@ -116,7 +170,7 @@ public void Debug_Multilines() var pagingLogger = new Mock(); var jobServerQueue = new Mock(); jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); - jobServerQueue.Setup(x => x.QueueWebConsoleLine(It.IsAny(), It.IsAny(),It.IsAny())).Callback((Guid id, string msg, long? lineNumber) => { hc.GetTrace().Info(msg); }); + jobServerQueue.Setup(x => x.QueueWebConsoleLine(It.IsAny(), It.IsAny(), It.IsAny())).Callback((Guid id, string msg, long? lineNumber) => { hc.GetTrace().Info(msg); }); hc.EnqueueInstance(pagingLogger.Object); hc.SetSingleton(jobServerQueue.Object); @@ -378,6 +432,177 @@ public void ActionResult_Lowercase() } } + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void PublishStepTelemetry_RegularStep_NoOpt() + { + using (TestHostContext hc = CreateTestContext()) + { + // Arrange: Create a job request message. + TaskOrchestrationPlanReference plan = new TaskOrchestrationPlanReference(); + TimelineReference timeline = new TimelineReference(); + Guid jobId = Guid.NewGuid(); + string jobName = "some job name"; + var jobRequest = new Pipelines.AgentJobRequestMessage(plan, timeline, jobId, jobName, jobName, null, null, null, new Dictionary(), new List(), new Pipelines.JobResources(), new Pipelines.ContextData.DictionaryContextData(), new Pipelines.WorkspaceOptions(), new List(), null, null, null, null); + jobRequest.Resources.Repositories.Add(new Pipelines.RepositoryResource() + { + Alias = Pipelines.PipelineConstants.SelfAlias, + Id = "github", + Version = "sha1" + }); + jobRequest.ContextData["github"] = new Pipelines.ContextData.DictionaryContextData(); + + // Arrange: Setup the paging logger. + var pagingLogger = new Mock(); + var jobServerQueue = new Mock(); + jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); + + hc.EnqueueInstance(pagingLogger.Object); + hc.SetSingleton(jobServerQueue.Object); + + var ec = new Runner.Worker.ExecutionContext(); + ec.Initialize(hc); + + // Act. + ec.InitializeJob(jobRequest, CancellationToken.None); + ec.Start(); + + ec.Complete(); + + // Assert. + Assert.Equal(0, ec.Global.StepsTelemetry.Count); + } + } + + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void PublishStepTelemetry_RegularStep() + { + using (TestHostContext hc = CreateTestContext()) + { + // Arrange: Create a job request message. + TaskOrchestrationPlanReference plan = new TaskOrchestrationPlanReference(); + TimelineReference timeline = new TimelineReference(); + Guid jobId = Guid.NewGuid(); + string jobName = "some job name"; + var jobRequest = new Pipelines.AgentJobRequestMessage(plan, timeline, jobId, jobName, jobName, null, null, null, new Dictionary(), new List(), new Pipelines.JobResources(), new Pipelines.ContextData.DictionaryContextData(), new Pipelines.WorkspaceOptions(), new List(), null, null, null, null); + jobRequest.Resources.Repositories.Add(new Pipelines.RepositoryResource() + { + Alias = Pipelines.PipelineConstants.SelfAlias, + Id = "github", + Version = "sha1" + }); + jobRequest.ContextData["github"] = new Pipelines.ContextData.DictionaryContextData(); + + // Arrange: Setup the paging logger. + var pagingLogger = new Mock(); + var jobServerQueue = new Mock(); + jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); + + hc.EnqueueInstance(pagingLogger.Object); + hc.SetSingleton(jobServerQueue.Object); + + var ec = new Runner.Worker.ExecutionContext(); + ec.Initialize(hc); + + // Act. + ec.InitializeJob(jobRequest, CancellationToken.None); + ec.Start(); + + ec.StepTelemetry.Type = "node16"; + ec.StepTelemetry.Action = "actions/checkout"; + ec.StepTelemetry.Ref = "v2"; + ec.StepTelemetry.IsEmbedded = false; + ec.StepTelemetry.StepId = Guid.NewGuid(); + ec.StepTelemetry.Stage = "main"; + + ec.AddIssue(new Issue() { Type = IssueType.Error, Message = "error" }); + ec.AddIssue(new Issue() { Type = IssueType.Warning, Message = "warning" }); + ec.AddIssue(new Issue() { Type = IssueType.Notice, Message = "notice" }); + ec.AddIssue(new Issue() { Type = IssueType.Error, Message = "error" }); + ec.AddIssue(new Issue() { Type = IssueType.Warning, Message = "warning" }); + ec.AddIssue(new Issue() { Type = IssueType.Notice, Message = "notice" }); + + ec.Complete(); + + // Assert. + Assert.Equal(1, ec.Global.StepsTelemetry.Count); + Assert.Equal("node16", ec.Global.StepsTelemetry.Single().Type); + Assert.Equal("actions/checkout", ec.Global.StepsTelemetry.Single().Action); + Assert.Equal("v2", ec.Global.StepsTelemetry.Single().Ref); + Assert.Equal(TaskResult.Succeeded, ec.Global.StepsTelemetry.Single().Result); + Assert.NotNull(ec.Global.StepsTelemetry.Single().ExecutionTimeInSeconds); + Assert.Equal(3, ec.Global.StepsTelemetry.Single().ErrorMessages.Count); + Assert.DoesNotContain(ec.Global.StepsTelemetry.Single().ErrorMessages, x => x.Contains("notice")); + } + } + + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void PublishStepTelemetry_EmbeddedStep() + { + using (TestHostContext hc = CreateTestContext()) + { + // Arrange: Create a job request message. + TaskOrchestrationPlanReference plan = new TaskOrchestrationPlanReference(); + TimelineReference timeline = new TimelineReference(); + Guid jobId = Guid.NewGuid(); + string jobName = "some job name"; + var jobRequest = new Pipelines.AgentJobRequestMessage(plan, timeline, jobId, jobName, jobName, null, null, null, new Dictionary(), new List(), new Pipelines.JobResources(), new Pipelines.ContextData.DictionaryContextData(), new Pipelines.WorkspaceOptions(), new List(), null, null, null, null); + jobRequest.Resources.Repositories.Add(new Pipelines.RepositoryResource() + { + Alias = Pipelines.PipelineConstants.SelfAlias, + Id = "github", + Version = "sha1" + }); + jobRequest.ContextData["github"] = new Pipelines.ContextData.DictionaryContextData(); + + // Arrange: Setup the paging logger. + var pagingLogger = new Mock(); + var pagingLogger2 = new Mock(); + var jobServerQueue = new Mock(); + jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); + + hc.EnqueueInstance(pagingLogger.Object); + hc.EnqueueInstance(pagingLogger2.Object); + hc.SetSingleton(jobServerQueue.Object); + + var ec = new Runner.Worker.ExecutionContext(); + ec.Initialize(hc); + + // Act. + ec.InitializeJob(jobRequest, CancellationToken.None); + ec.Start(); + + var embeddedStep = ec.CreateChild(Guid.NewGuid(), "action_1_pre", "action_1_pre", null, null, ActionRunStage.Main, isEmbedded: true); + embeddedStep.Start(); + + embeddedStep.StepTelemetry.Type = "node16"; + embeddedStep.StepTelemetry.Action = "actions/checkout"; + embeddedStep.StepTelemetry.Ref = "v2"; + + embeddedStep.AddIssue(new Issue() { Type = IssueType.Error, Message = "error" }); + embeddedStep.AddIssue(new Issue() { Type = IssueType.Warning, Message = "warning" }); + embeddedStep.AddIssue(new Issue() { Type = IssueType.Notice, Message = "notice" }); + + embeddedStep.PublishStepTelemetry(); + + // Assert. + Assert.Equal(1, ec.Global.StepsTelemetry.Count); + Assert.Equal("node16", ec.Global.StepsTelemetry.Single().Type); + Assert.Equal("actions/checkout", ec.Global.StepsTelemetry.Single().Action); + Assert.Equal("v2", ec.Global.StepsTelemetry.Single().Ref); + Assert.Equal(ActionRunStage.Main.ToString(), ec.Global.StepsTelemetry.Single().Stage); + Assert.True(ec.Global.StepsTelemetry.Single().IsEmbedded); + Assert.Null(ec.Global.StepsTelemetry.Single().Result); + Assert.Null(ec.Global.StepsTelemetry.Single().ExecutionTimeInSeconds); + Assert.Equal(0, ec.Global.StepsTelemetry.Single().ErrorMessages.Count); + } + } + private TestHostContext CreateTestContext([CallerMemberName] String testName = "") { var hc = new TestHostContext(this, testName); diff --git a/src/Test/L0/Worker/HandlerL0.cs b/src/Test/L0/Worker/HandlerL0.cs new file mode 100644 index 00000000000..f1878b2be39 --- /dev/null +++ b/src/Test/L0/Worker/HandlerL0.cs @@ -0,0 +1,88 @@ +using System; +using System.Runtime.CompilerServices; +using GitHub.DistributedTask.Pipelines; +using GitHub.DistributedTask.WebApi; +using GitHub.Runner.Sdk; +using GitHub.Runner.Worker; +using GitHub.Runner.Worker.Handlers; +using Moq; +using Xunit; + +namespace GitHub.Runner.Common.Tests.Worker +{ + public sealed class HandlerL0 + { + private Mock _ec; + private ActionsStepTelemetry _stepTelemetry; + private TestHostContext CreateTestContext([CallerMemberName] String testName = "") + { + var hc = new TestHostContext(this, testName); + _stepTelemetry = new ActionsStepTelemetry(); + _ec = new Mock(); + _ec.SetupAllProperties(); + _ec.Setup(x => x.StepTelemetry).Returns(_stepTelemetry); + + var trace = hc.GetTrace(); + _ec.Setup(x => x.Write(It.IsAny(), It.IsAny())).Callback((string tag, string message) => { trace.Info($"[{tag}]{message}"); }); + + hc.EnqueueInstance(new Mock().Object); + return hc; + } + + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void PrepareExecution_PopulateTelemetry_RepoActions() + { + using (TestHostContext hc = CreateTestContext()) + { + // Arrange. + var nodeHandler = new NodeScriptActionHandler(); + nodeHandler.Initialize(hc); + + nodeHandler.ExecutionContext = _ec.Object; + nodeHandler.Action = new RepositoryPathReference() + { + Name = "actions/checkout", + Ref = "v2" + }; + + // Act. + nodeHandler.PrepareExecution(ActionRunStage.Main); + hc.GetTrace().Info($"Telemetry: {StringUtil.ConvertToJson(_stepTelemetry)}"); + + // Assert. + Assert.Equal("repository", _stepTelemetry.Type); + Assert.Equal("actions/checkout", _stepTelemetry.Action); + Assert.Equal("v2", _stepTelemetry.Ref); + } + } + + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void PrepareExecution_PopulateTelemetry_DockerActions() + { + using (TestHostContext hc = CreateTestContext()) + { + // Arrange. + var nodeHandler = new NodeScriptActionHandler(); + nodeHandler.Initialize(hc); + + nodeHandler.ExecutionContext = _ec.Object; + nodeHandler.Action = new ContainerRegistryReference() + { + Image = "ubuntu:20.04" + }; + + // Act. + nodeHandler.PrepareExecution(ActionRunStage.Main); + hc.GetTrace().Info($"Telemetry: {StringUtil.ConvertToJson(_stepTelemetry)}"); + + // Assert. + Assert.Equal("docker", _stepTelemetry.Type); + Assert.Equal("ubuntu:20.04", _stepTelemetry.Action); + } + } + } +}