fix: escape command data the runner writes itself (#1120)

Command data is percent-escaped on the wire because Gitea's job log cannot carry a newline, and the renderer decodes it.

1. Unescaping iterated a map, so order was random per process: `%250A` decoded to a newline instead of a literal `%0A` about two runs in three. Now a precompiled `strings.NewReplacer`.
1. Escape the data of command lines the runner writes itself (`##[error]`, `::group::Run …`), so decoding returns the original text instead of mangling a `%`. Multi-line runner errors also get real line breaks instead of a literal `\n`.
1. Register secrets in escaped form too — one containing `%` reaches the log as `%25…` and was never masked.
1. Decode in `jobLogFormatter`, so `gitea-runner exec` matches the web view.

## Relation to the Gitea PR

https://github.com/go-gitea/gitea/pull/38659 makes the renderer decode command data. Point 2 is required by it; the rest stand alone. Either order works — until both land, a new runner on old Gitea shows `%25`, an old runner on new Gitea shows the mangling point 2 fixes.
Co-authored-by: bircni <bircni@icloud.com>
Reviewed-on: https://gitea.com/gitea/runner/pulls/1120
Reviewed-by: bircni <bircni@icloud.com>
Co-authored-by: silverwind <me@silverwind.io>

act/runner/command.go

@@ -154,30 +154,25 @@ func parseKeyValuePairs(kvPairs, separator string) map[string]string {
 	return rtn
 }
 
+// A Replacer never rescans what it wrote, so "%250A" stays a literal "%0A".
+var (
+	commandDataEscaper       = strings.NewReplacer("%", "%25", "\r", "%0D", "\n", "%0A")
+	commandDataUnescaper     = strings.NewReplacer("%25", "%", "%0D", "\r", "%0A", "\n")
+	commandPropertyUnescaper = strings.NewReplacer("%25", "%", "%0D", "\r", "%0A", "\n", "%3A", ":", "%2C", ",")
+)
+
+// escapeCommandData encodes the data part of a "::cmd::" or "##[cmd]" line the runner writes itself,
+// so the log renderer decodes it back. Lines forwarded from step output are already escaped.
+func escapeCommandData(arg string) string {
+	return commandDataEscaper.Replace(arg)
+}
+
 func UnescapeCommandData(arg string) string {
-	escapeMap := map[string]string{
+	return commandDataUnescaper.Replace(arg)
-		"%25": "%",
-		"%0D": "\r",
-		"%0A": "\n",
-	}
-	for k, v := range escapeMap {
-		arg = strings.ReplaceAll(arg, k, v)
-	}
-	return arg
 }
 
 func unescapeCommandProperty(arg string) string {
-	escapeMap := map[string]string{
+	return commandPropertyUnescaper.Replace(arg)
-		"%25": "%",
-		"%0D": "\r",
-		"%0A": "\n",
-		"%3A": ":",
-		"%2C": ",",
-	}
-	for k, v := range escapeMap {
-		arg = strings.ReplaceAll(arg, k, v)
-	}
-	return arg
 }
 
 func unescapeKvPairs(kvPairs map[string]string) map[string]string {

act/runner/command_test.go

@@ -214,3 +214,10 @@ func TestSaveState(t *testing.T) {
 
 	assert.Equal(t, "state-value", rc.IntraActionState["step"]["state-name"])
 }
+
+func TestEscapeCommandData(t *testing.T) {
+	a := assert.New(t)
+
+	a.Equal("a%25b%0Dc%0Ad%250A", escapeCommandData("a%b\rc\nd%0A"))
+	a.Equal("a%b\rc\nd%0A", UnescapeCommandData("a%25b%0Dc%0Ad%250A"))
+}

act/runner/job_executor.go

@@ -66,7 +66,7 @@ func reportStepError(ctx context.Context, rc *RunContext, err error) {
 		rc.markInterrupted(ctx.Err())
 		return
 	}
-	common.Logger(ctx).Errorf("##[error]%v", err)
+	common.Logger(ctx).Errorf("##[error]%s", escapeCommandData(err.Error()))
 	common.SetJobError(ctx, err)
 	rc.markFailed()
 }

act/runner/logger.go

@@ -175,6 +175,10 @@ func AppendSecretMasker(oldnew []string, v string) []string {
 		// formatted JSON secrets could otherwise mask {,[,],} everywhere
 		if len(tm) > 1 {
 			ret = append(ret, tm, "***")
+			// command data reaches the log escaped, so "pass%word" also arrives as "pass%25word"
+			if strings.ContainsAny(tm, "%\r\n") {
+				ret = append(ret, escapeCommandData(tm), "***")
+			}
 		}
 	}
 
@@ -230,6 +234,11 @@ type jobLogFormatter struct {
 func (f *jobLogFormatter) Format(entry *logrus.Entry) ([]byte, error) {
 	b := &bytes.Buffer{}
 
+	// the web renderer decodes command data, so this local view has to as well
+	if _, _, _, ok := tryParseRawActionCommand(entry.Message + "\n"); ok {
+		entry.Message = UnescapeCommandData(entry.Message)
+	}
+
 	if f.isColored(entry) {
 		f.printColored(b, entry)
 	} else {

act/runner/logger_test.go

@@ -4,11 +4,13 @@
 package runner
 
 import (
+	"io"
 	"strings"
 	"testing"
 
 	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 func TestValueMasker(t *testing.T) {
@@ -33,6 +35,12 @@ func TestValueMasker(t *testing.T) {
 			masks:      []string{"PRIVATE_KEY_BEGIN\ndsdfseffefsefes\ndsdfseffefsefes\ndsdfseffefsefes\ndsdfseffefsefes\ndsdfseffefsefes\ndsdfseffefsefes\ndsdfseffefsefes\ndsdfseffefsefes\ndsdfseffefsefes\nPRIVATE_KEY_END"},
 			disallowed: []string{"KEY", "dsdfseffefsefes", "PRIVATE_KEY_END"},
 		},
+		{
+			name:       "Secret containing a percent sign",
+			lines:      "##[error]login failed for pass%25word",
+			secrets:    map[string]string{"TOKEN": "pass%word"},
+			disallowed: []string{"pass%25word"},
+		},
 	}
 	for _, entry := range table {
 		t.Run(entry.name, func(t *testing.T) {
@@ -50,3 +58,17 @@ func TestValueMasker(t *testing.T) {
 		})
 	}
 }
+
+func TestJobLogFormatterDecodesCommandData(t *testing.T) {
+	logger := logrus.New()
+	logger.Out = io.Discard
+	format := func(message string) string {
+		out, err := (&jobLogFormatter{}).Format(&logrus.Entry{Logger: logger, Message: message, Data: logrus.Fields{rawOutputField: true}})
+		require.NoError(t, err)
+		return string(out)
+	}
+
+	assert.Contains(t, format("##[error]deploy 50%25 traffic"), "##[error]deploy 50% traffic")
+	// a plain line is not command data and keeps its literal escapes
+	assert.Contains(t, format("progress 50%25 done"), "progress 50%25 done")
+}

act/runner/step.go

@@ -181,7 +181,7 @@ func runStepExecutor(step step, stage stepStage, executor common.Executor) commo
 			}
 
 			if continueOnError {
-				logger.Errorf("##[error]%v", err)
+				logger.Errorf("##[error]%s", escapeCommandData(err.Error()))
 				logger.Infof("Failed but continue next step")
 				err = nil
 				stepResult.Conclusion = model.StepStatusSuccess

act/runner/step_run.go

@@ -63,7 +63,7 @@ func (sr *stepRun) printRunScriptActionDetails(ctx context.Context) {
 
 	normalized := strings.TrimRight(strings.ReplaceAll(sr.interpolatedScript, "\r\n", "\n"), "\n")
 
-	rawLogger.Infof("::group::Run %s", sr.runScriptGroupTitle(normalized))
+	rawLogger.Infof("::group::Run %s", escapeCommandData(sr.runScriptGroupTitle(normalized)))
 
 	if normalized != "" {
 		for line := range strings.SplitSeq(normalized, "\n") {
@@ -90,7 +90,7 @@ func printRunActionHeader(ctx context.Context, step *model.Step, env map[string]
 	if step.Name != "" {
 		title = step.Name
 	}
-	rawLogger.Infof("::group::Run %s", title)
+	rawLogger.Infof("::group::Run %s", escapeCommandData(title))
 
 	if len(step.With) > 0 {
 		rawLogger.Infof("with:")