Implement new echo behavior and command (#139)

* Remove controlling echoing by command

* Add 'echo on' and 'echo off' action commands

* PR feedback and add L0 tests

* Register new command

* Eric's PR feedback

* Tweak logging a bit

* Rename EchoOnActionCommandSuccess -> EchoOnActionCommand

* More PR reaction

* Make warning messages in Action Commands not rely on context from echo commands

src/Runner.Common/ExtensionManager.cs

@@ -54,6 +54,7 @@ namespace GitHub.Runner.Common
                     Add<T>(extensions, "GitHub.Runner.Worker.DebugCommandExtension, Runner.Worker");
                     Add<T>(extensions, "GitHub.Runner.Worker.GroupCommandExtension, Runner.Worker");
                     Add<T>(extensions, "GitHub.Runner.Worker.EndGroupCommandExtension, Runner.Worker");
+                    Add<T>(extensions, "GitHub.Runner.Worker.EchoCommandExtension, Runner.Worker");
                     break;
                 default:
                     // This should never happen.

src/Runner.Worker/ActionCommandManager.cs

@@ -107,26 +107,35 @@ namespace GitHub.Runner.Worker
                     }
                     else if (_commandExtensions.TryGetValue(actionCommand.Command, out IActionCommandExtension extension))
                     {
-                        bool omitEcho;
+                        bool commandHasBeenOutput = false;
+
                         try
                         {
-                            extension.ProcessCommand(context, input, actionCommand, out omitEcho);
+                            if (context.EchoOnActionCommand)
+                            {
+                                context.Output(input);
+                                context.Debug($"Processing command '{actionCommand.Command}'");
+                                commandHasBeenOutput = true;
+                            }
+
+                            extension.ProcessCommand(context, input, actionCommand);
+
+                            if (context.EchoOnActionCommand)
+                            {
+                                context.Debug($"Processed command '{actionCommand.Command}' successfully");
+                            }
                         }
                         catch (Exception ex)
                         {
-                            omitEcho = true;
+                            if (!commandHasBeenOutput)
+                            {
                                 context.Output(input);
+                            }
+
                             context.Error($"Unable to process command '{input}' successfully.");
                             context.Error(ex);
                             context.CommandResult = TaskResult.Failed;
                         }
-
-                        if (!omitEcho)
-                        {
-                            context.Output(input);
-                            context.Debug($"Processed command");
-                        }
-
                     }
                     else
                     {
@@ -143,7 +152,7 @@ namespace GitHub.Runner.Worker
     {
         string Command { get; }
 
-        void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho);
+        void ProcessCommand(IExecutionContext context, string line, ActionCommand command);
     }
 
     public sealed class InternalPluginSetRepoPathCommandExtension : RunnerService, IActionCommandExtension
@@ -152,7 +161,7 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
             if (!command.Properties.TryGetValue(SetRepoPathCommandProperties.repoFullName, out string repoFullName) || string.IsNullOrEmpty(repoFullName))
             {
@@ -166,8 +175,6 @@ namespace GitHub.Runner.Worker
 
             var directoryManager = HostContext.GetService<IPipelineDirectoryManager>();
             var trackingConfig = directoryManager.UpdateRepositoryDirectory(context, repoFullName, command.Data, StringUtil.ConvertToBoolean(workspaceRepo));
-
-            omitEcho = true;
         }
 
         private static class SetRepoPathCommandProperties
@@ -183,7 +190,7 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
             if (!command.Properties.TryGetValue(SetEnvCommandProperties.Name, out string envName) || string.IsNullOrEmpty(envName))
             {
@@ -192,9 +199,7 @@ namespace GitHub.Runner.Worker
 
             context.EnvironmentVariables[envName] = command.Data;
             context.SetEnvContext(envName, command.Data);
-            context.Output(line);
             context.Debug($"{envName}='{command.Data}'");
-            omitEcho = true;
         }
 
         private static class SetEnvCommandProperties
@@ -209,7 +214,7 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
             if (!command.Properties.TryGetValue(SetOutputCommandProperties.Name, out string outputName) || string.IsNullOrEmpty(outputName))
             {
@@ -217,9 +222,7 @@ namespace GitHub.Runner.Worker
             }
 
             context.SetOutput(outputName, command.Data, out var reference);
-            context.Output(line);
             context.Debug($"{reference}='{command.Data}'");
-            omitEcho = true;
         }
 
         private static class SetOutputCommandProperties
@@ -234,7 +237,7 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
             if (!command.Properties.TryGetValue(SaveStateCommandProperties.Name, out string stateName) || string.IsNullOrEmpty(stateName))
             {
@@ -243,7 +246,6 @@ namespace GitHub.Runner.Worker
 
             context.IntraActionState[stateName] = command.Data;
             context.Debug($"Save intra-action state {stateName} = {command.Data}");
-            omitEcho = true;
         }
 
         private static class SaveStateCommandProperties
@@ -258,19 +260,17 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
             if (string.IsNullOrWhiteSpace(command.Data))
             {
-                context.Warning("Can't add secret mask for empty string.");
+                context.Warning("Can't add secret mask for empty string in ##[add-mask] command.");
             }
             else
             {
                 HostContext.SecretMasker.AddValue(command.Data);
                 Trace.Info($"Add new secret mask with length of {command.Data.Length}");
             }
-
-            omitEcho = true;
         }
     }
 
@@ -280,12 +280,11 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
             ArgUtil.NotNullOrEmpty(command.Data, "path");
             context.PrependPath.RemoveAll(x => string.Equals(x, command.Data, StringComparison.CurrentCulture));
             context.PrependPath.Add(command.Data);
-            omitEcho = false;
         }
     }
 
@@ -295,9 +294,8 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
-            omitEcho = false;
             var file = command.Data;
 
             // File is required
@@ -342,23 +340,22 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
-            omitEcho = false;
             command.Properties.TryGetValue(RemoveMatcherCommandProperties.Owner, out string owner);
             var file = command.Data;
 
             // Owner and file are mutually exclusive
             if (!string.IsNullOrEmpty(owner) && !string.IsNullOrEmpty(file))
             {
-                context.Warning("Either specify a matcher owner name or a file path. Both values cannot be set.");
+                context.Warning("Either specify an owner name or a file path in ##[remove-matcher] command. Both values cannot be set.");
                 return;
             }
 
             // Owner or file is required
             if (string.IsNullOrEmpty(owner) && string.IsNullOrEmpty(file))
             {
-                context.Warning("Either a matcher owner name or a file path must be specified.");
+                context.Warning("Either an owner name or a file path must be specified in ##[remove-matcher] command.");
                 return;
             }
 
@@ -410,9 +407,8 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string inputLine, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string inputLine, ActionCommand command)
         {
-            omitEcho = true;
             context.Debug(command.Data);
         }
     }
@@ -438,10 +434,8 @@ namespace GitHub.Runner.Worker
 
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string inputLine, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string inputLine, ActionCommand command)
         {
-            omitEcho = true;
-
             Issue issue = new Issue()
             {
                 Category = "General",
@@ -468,11 +462,37 @@ namespace GitHub.Runner.Worker
         public abstract string Command { get; }
         public Type ExtensionType => typeof(IActionCommandExtension);
 
-        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command, out bool omitEcho)
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
         {
             var data = this is GroupCommandExtension ? command.Data : string.Empty;
             context.Output($"##[{Command}]{data}");
-            omitEcho = true;
+        }
+    }
+
+    public sealed class EchoCommandExtension : RunnerService, IActionCommandExtension
+    {
+        public string Command => "echo";
+
+        public Type ExtensionType => typeof(IActionCommandExtension);
+
+        public void ProcessCommand(IExecutionContext context, string line, ActionCommand command)
+        {
+            ArgUtil.NotNullOrEmpty(command.Data, "value");
+
+            switch (command.Data.Trim().ToUpperInvariant())
+            {
+                case "ON":
+                    context.EchoOnActionCommand = true;
+                    context.Debug("Setting echo command value to 'on'");
+                    break;
+                case "OFF":
+                    context.EchoOnActionCommand = false;
+                    context.Debug("Setting echo command value to 'off'");
+                    break;
+                default:
+                    throw new Exception($"Invalid echo command value. Possible values can be: 'on', 'off'. Current value is: '{command.Data}'.");
+                    break;
+            }
         }
     }
 }

src/Runner.Worker/ExecutionContext.cs

@@ -12,14 +12,14 @@ using GitHub.Services.WebApi;
 using GitHub.DistributedTask.Pipelines;
 using GitHub.DistributedTask.Pipelines.ContextData;
 using GitHub.DistributedTask.WebApi;
-using Pipelines = GitHub.DistributedTask.Pipelines;
-using ObjectTemplating = GitHub.DistributedTask.ObjectTemplating;
 using GitHub.Runner.Common.Util;
 using GitHub.Runner.Common;
 using GitHub.Runner.Sdk;
 using Newtonsoft.Json;
 using System.Text;
 using System.Collections;
+using ObjectTemplating = GitHub.DistributedTask.ObjectTemplating;
+using Pipelines = GitHub.DistributedTask.Pipelines;
 
 namespace GitHub.Runner.Worker
 {
@@ -62,6 +62,8 @@ namespace GitHub.Runner.Worker
         // Only job level ExecutionContext has PostJobSteps
         Stack<IStep> PostJobSteps { get; }
 
+        bool EchoOnActionCommand { get; set; }
+
         // Initialize
         void InitializeJob(Pipelines.AgentJobRequestMessage message, CancellationToken token);
         void CancelToken();
@@ -153,6 +155,8 @@ namespace GitHub.Runner.Worker
         // Only job level ExecutionContext has PostJobSteps
         public Stack<IStep> PostJobSteps { get; private set; }
 
+        public bool EchoOnActionCommand { get; set; }
+
 
         public TaskResult? Result
         {
@@ -292,6 +296,7 @@ namespace GitHub.Runner.Worker
             child.PrependPath = PrependPath;
             child.Container = Container;
             child.ServiceContainers = ServiceContainers;
+            child.EchoOnActionCommand = EchoOnActionCommand;
 
             if (recordOrder != null)
             {
@@ -704,6 +709,9 @@ namespace GitHub.Runner.Worker
             _logger = HostContext.CreateService<IPagingLogger>();
             _logger.Setup(_mainTimelineId, _record.Id);
 
+            // Initialize 'echo on action command success' property, default to false, unless Step_Debug is set
+            EchoOnActionCommand = Variables.Step_Debug ?? false;
+
             // Verbosity (from GitHub.Step_Debug).
             WriteDebug = Variables.Step_Debug ?? false;
 

src/Test/L0/Worker/ActionCommandManagerL0.cs

@@ -5,6 +5,7 @@ using GitHub.DistributedTask.WebApi;
 using GitHub.Runner.Worker;
 using Moq;
 using Xunit;
+using Pipelines = GitHub.DistributedTask.Pipelines;
 
 namespace GitHub.Runner.Common.Tests.Worker
 {
@@ -146,5 +147,159 @@ namespace GitHub.Runner.Common.Tests.Worker
                 Assert.True(commandManager.TryProcessCommand(_ec.Object, "##[set-env name=foo]bar"));
             }
         }
+
+        [Fact]
+        [Trait("Level", "L0")]
+        [Trait("Category", "Worker")]
+        public void EchoProcessCommand()
+        {
+            using (TestHostContext _hc = new TestHostContext(this))
+            {
+                var extensionManager = new Mock<IExtensionManager>();
+                var echoCommand = new EchoCommandExtension();
+                echoCommand.Initialize(_hc);
+
+                extensionManager.Setup(x => x.GetExtensions<IActionCommandExtension>())
+                               .Returns(new List<IActionCommandExtension>() { echoCommand });
+                _hc.SetSingleton<IExtensionManager>(extensionManager.Object);
+
+                Mock<IExecutionContext> _ec = new Mock<IExecutionContext>();
+                _ec.Setup(x => x.Write(It.IsAny<string>(), It.IsAny<string>()))
+                   .Returns((string tag, string line) =>
+                            {
+                                _hc.GetTrace().Info($"{tag} {line}");
+                                return 1;
+                            });
+
+                _ec.SetupAllProperties();
+
+                ActionCommandManager commandManager = new ActionCommandManager();
+                commandManager.Initialize(_hc);
+
+                Assert.False(_ec.Object.EchoOnActionCommand);
+
+                Assert.True(commandManager.TryProcessCommand(_ec.Object, "::echo::on"));
+                Assert.True(_ec.Object.EchoOnActionCommand);
+
+                Assert.True(commandManager.TryProcessCommand(_ec.Object, "::echo::off"));
+                Assert.False(_ec.Object.EchoOnActionCommand);
+
+                Assert.True(commandManager.TryProcessCommand(_ec.Object, "::echo::ON"));
+                Assert.True(_ec.Object.EchoOnActionCommand);
+
+                Assert.True(commandManager.TryProcessCommand(_ec.Object, "::echo::Off   "));
+                Assert.False(_ec.Object.EchoOnActionCommand);
+            }
+        }
+
+        [Fact]
+        [Trait("Level", "L0")]
+        [Trait("Category", "Worker")]
+        public void EchoProcessCommandDebugOn()
+        {
+            using (TestHostContext _hc = new TestHostContext(this))
+            {
+                // Set up a few things
+                // 1. Job request message (with ACTIONS_STEP_DEBUG = true)
+                TaskOrchestrationPlanReference plan = new TaskOrchestrationPlanReference();
+                TimelineReference timeline = new TimelineReference();
+                JobEnvironment environment = new JobEnvironment();
+                environment.SystemConnection = new ServiceEndpoint();
+                List<TaskInstance> tasks = new List<TaskInstance>();
+                Guid JobId = Guid.NewGuid();
+                string jobName = "some job name";
+                var jobRequest = Pipelines.AgentJobRequestMessageUtil.Convert(new AgentJobRequestMessage(plan, timeline, JobId, jobName, jobName, environment, tasks));
+                jobRequest.Resources.Repositories.Add(new Pipelines.RepositoryResource()
+                {
+                    Alias = Pipelines.PipelineConstants.SelfAlias,
+                    Id = "github",
+                    Version = "sha1"
+                });
+                jobRequest.ContextData["github"] = new Pipelines.ContextData.DictionaryContextData();
+                jobRequest.Variables["ACTIONS_STEP_DEBUG"] = "true";
+
+                // Some service dependencies
+                var jobServerQueue = new Mock<IJobServerQueue>();
+                jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny<Guid>(), It.IsAny<TimelineRecord>()));
+
+                _hc.SetSingleton(jobServerQueue.Object);
+
+                var extensionManager = new Mock<IExtensionManager>();
+                var echoCommand = new EchoCommandExtension();
+                echoCommand.Initialize(_hc);
+
+                extensionManager.Setup(x => x.GetExtensions<IActionCommandExtension>())
+                               .Returns(new List<IActionCommandExtension>() { echoCommand });
+                _hc.SetSingleton<IExtensionManager>(extensionManager.Object);
+
+                var configurationStore = new Mock<IConfigurationStore>();
+                configurationStore.Setup(x => x.GetSettings()).Returns(new RunnerSettings());
+                _hc.SetSingleton(configurationStore.Object);
+
+                var pagingLogger = new Mock<IPagingLogger>();
+                _hc.EnqueueInstance(pagingLogger.Object);
+
+                ActionCommandManager commandManager = new ActionCommandManager();
+                commandManager.Initialize(_hc);
+
+                var _ec = new Runner.Worker.ExecutionContext();
+                _ec.Initialize(_hc);
+
+                // Initialize the job (to exercise logic that sets EchoOnActionCommand)
+                _ec.InitializeJob(jobRequest, System.Threading.CancellationToken.None);
+
+                _ec.Complete();
+
+                Assert.True(_ec.EchoOnActionCommand);
+
+                Assert.True(commandManager.TryProcessCommand(_ec, "::echo::off"));
+                Assert.False(_ec.EchoOnActionCommand);
+
+                Assert.True(commandManager.TryProcessCommand(_ec, "::echo::on"));
+                Assert.True(_ec.EchoOnActionCommand);
+            }
+        }
+
+
+        [Fact]
+        [Trait("Level", "L0")]
+        [Trait("Category", "Worker")]
+        public void EchoProcessCommandInvalid()
+        {
+            using (TestHostContext _hc = new TestHostContext(this))
+            {
+                var extensionManager = new Mock<IExtensionManager>();
+                var echoCommand = new EchoCommandExtension();
+                echoCommand.Initialize(_hc);
+
+                extensionManager.Setup(x => x.GetExtensions<IActionCommandExtension>())
+                               .Returns(new List<IActionCommandExtension>() { echoCommand });
+                _hc.SetSingleton<IExtensionManager>(extensionManager.Object);
+
+                Mock<IExecutionContext> _ec = new Mock<IExecutionContext>();
+                _ec.Setup(x => x.Write(It.IsAny<string>(), It.IsAny<string>()))
+                   .Returns((string tag, string line) =>
+                            {
+                                _hc.GetTrace().Info($"{tag} {line}");
+                                return 1;
+                            });
+
+                _ec.SetupAllProperties();
+
+                ActionCommandManager commandManager = new ActionCommandManager();
+                commandManager.Initialize(_hc);
+
+                // Echo commands below are considered "processed", but are invalid
+                // 1. Invalid echo value
+                Assert.True(commandManager.TryProcessCommand(_ec.Object, "::echo::invalid"));
+                Assert.Equal(TaskResult.Failed, _ec.Object.CommandResult);
+                Assert.False(_ec.Object.EchoOnActionCommand);
+
+                // 2. No value
+                Assert.True(commandManager.TryProcessCommand(_ec.Object, "::echo::"));
+                Assert.Equal(TaskResult.Failed, _ec.Object.CommandResult);
+                Assert.False(_ec.Object.EchoOnActionCommand);
+            }
+        }
     }
 }