fix: prevent masking gaps in workflow command logs (#1384)

Mask partially escaped workflow command output and complete one-character values while preserving literal output and stream line endings.

Fixes: https://gitea.com/gitea/runner/issues/300
Reviewed-on: https://gitea.com/gitea/runner/pulls/1384
Reviewed-by: bircni <[email protected]>

DEVELOPMENT.md

@@ -23,11 +23,14 @@ depending on the prefix:
   covers both forms: it escapes `%` first, so a literal `%3B` becomes `%253B` that the extra
   `##[…]` rules cannot match, and a raw `;` or `]` is never decoded. It is also what makes
   multi-line work, `\n` becomes `%0A` and the UI turns it back into a line break.
-- **Forwarding a command from step output?** Leave the payload alone, it arrived escaped and is
+- **Forwarding a command from step output?** Preserve its escaping unless masking changes it.
-  decoded once. Decoding here double-decodes and destroys multi-line.
+  Decoding for display happens in the UI.
 - **No prefix?** Do not escape, and split multi-line values into one row each.
-- **Interpolating a secret?** Masking runs after escaping, so `AppendSecretMasker` registers the
+- **Interpolating a secret?** Masking runs after escaping. Recognised command payloads are
-  encoded forms too.
+  normalised before masking to cover partially escaped values. Their original escaping is
+  preserved when no replacement occurs. `AppendSecretMasker` also registers encoded forms for
+  other output. Complete nonblank one-character values are masked, while one-byte fragments
+  of multiline values are skipped.
 - Command *properties* also escape `%3A` and `%2C`, which the UI never decodes, so the command
   handler folds an annotation's location into its decoded message and escapes the result again.
 

act/runner/command_test.go

@@ -193,6 +193,11 @@ func TestCommandLogWriter(t *testing.T) {
 		log   []string
 		masks []string
 	}{
+		{
+			name:  "mask commands decode modern and legacy escapes once",
+			steps: [][]string{{"::add-mask::%25", "##[add-mask]alpha beta%3Bgamma%5Ddelta%250A"}},
+			masks: []string{"%", "alpha beta;gamma]delta%0A"},
+		},
 		{
 			name: "applied commands are hidden unless echoed",
 			steps: [][]string{{

act/runner/logger.go

@@ -263,29 +263,27 @@ func AppendSecretMaskers(oldnew []string, secrets map[string]string) []string {
 	return oldnew
 }
 
-// AppendSecretMasker registers v and each of its lines, as GitHub does.
+// AppendSecretMasker skips one-byte line fragments to avoid masking punctuation from structured secrets.
 func AppendSecretMasker(oldnew []string, v string) []string {
 	ret := appendMaskedValue(oldnew, v)
 	for l := range strings.FieldsFuncSeq(v, func(r rune) bool { return r == '\r' || r == '\n' }) {
-		ret = appendMaskedValue(ret, strings.TrimSpace(l))
+		if line := strings.TrimSpace(l); len(line) > 1 {
+			ret = appendMaskedValue(ret, line)
+		}
 	}
 	return ret
 }
 
-// appendMaskedValue registers one value and every shape it takes on its way into a log.
 func appendMaskedValue(ret []string, v string) []string {
-	// formatted JSON secrets could otherwise mask {,[,],} everywhere
+	if strings.TrimSpace(v) == "" || slices.Contains(ret, v) {
-	if len(strings.TrimSpace(v)) <= 1 || slices.Contains(ret, v) {
 		return ret
 	}
 	ret = append(ret, v, "***")
-	// command data reaches the log escaped, so "pass%word" also arrives as "pass%25word"
 	if strings.ContainsAny(v, "%\r\n") {
 		ret = append(ret, EscapeCommandData(v), "***")
 	}
 	for _, encode := range secretValueEncoders {
 		encoded := encode(v)
-		// An encoding that leaves the value unchanged is already masked above.
 		if encoded == v || len(encoded) <= 1 || slices.Contains(ret, encoded) {
 			continue
 		}
@@ -319,7 +317,7 @@ func valueMasker(insecureSecrets bool, oldnew []string) entryProcessor {
 		masks := Masks(ctx)
 
 		if len(*masks) == 0 {
-			r.Message = defReplacer.Replace(r.Message)
+			r.Message = MaskLog(r.Message, defReplacer)
 			return r
 		}
 
@@ -339,12 +337,42 @@ func valueMasker(insecureSecrets bool, oldnew []string) entryProcessor {
 		cmasker := replacer
 		mu.Unlock()
 
-		r.Message = cmasker.Replace(r.Message)
+		r.Message = MaskLog(r.Message, cmasker)
 
 		return r
 	}
 }
 
+// MaskLog decodes command data before masking to cover partially escaped values.
+func MaskLog(message string, replacer *strings.Replacer) string {
+	var command, data string
+	var found bool
+	unescape := UnescapeCommandData
+	if strings.HasPrefix(message, "##[") {
+		command, data, found = strings.Cut(message[3:], "]")
+		unescape = UnescapeLegacyCommand
+	} else if strings.HasPrefix(message, "::") {
+		command, data, found = strings.Cut(message[2:], "::")
+		if name, _, properties := strings.Cut(command, " "); properties {
+			switch name {
+			case "error", "warning", "notice", "debug":
+				command = name
+			}
+		}
+	}
+	switch command {
+	case "error", "warning", "notice", "debug", "group", "endgroup", "add-matcher":
+		if found {
+			trimmedData := strings.TrimRight(data, "\r\n")
+			normalized := message[:len(message)-len(data)] + EscapeCommandData(unescape(trimmedData)) + data[len(trimmedData):]
+			if masked := replacer.Replace(normalized); masked != normalized {
+				return masked
+			}
+		}
+	}
+	return replacer.Replace(message)
+}
+
 type maskedHandler struct {
 	logging.Handler
 	masker entryProcessor

act/runner/logger_test.go

@@ -28,6 +28,7 @@ func TestValueMasker(t *testing.T) {
 		secrets    map[string]string
 		masks      []string
 		disallowed []string
+		want       string
 	}{
 		{
 			name:  "Multiline Private Key",
@@ -49,6 +50,60 @@ func TestValueMasker(t *testing.T) {
 			secrets:    map[string]string{"TOKEN": "pass%word"},
 			disallowed: []string{"pass%25word"},
 		},
+		{
+			name:  "one-character mask",
+			lines: "%",
+			masks: []string{"%"},
+			want:  "***",
+		},
+		{
+			name:    "fully escaped legacy secret",
+			lines:   "##[group]alpha beta%3Bgamma%5Ddelta",
+			secrets: map[string]string{"TOKEN": "alpha beta;gamma]delta"},
+			want:    "##[group]***",
+		},
+		{
+			name:  "partially escaped legacy mask",
+			lines: "##[group]alpha beta%3Bgamma]delta",
+			masks: []string{"alpha beta;gamma]delta"},
+			want:  "##[group]***",
+		},
+		{
+			name:  "partially escaped modern mask preserves unrelated escapes",
+			lines: "::group::alpha%25beta%gamma tail%250A%0A",
+			masks: []string{"alpha%beta%gamma"},
+			want:  "::group::*** tail%250A%0A",
+		},
+		{
+			name:  "command escapes are decoded once",
+			lines: "##[group]alpha%253Bbeta%5Dgamma",
+			masks: []string{"alpha;beta]gamma"},
+			want:  "##[group]alpha%253Bbeta%5Dgamma",
+		},
+		{
+			name:  "plain output preserves escapes",
+			lines: "alpha beta%3Bgamma%5Ddelta",
+			masks: []string{"alpha beta;gamma]delta"},
+			want:  "alpha beta%3Bgamma%5Ddelta",
+		},
+		{
+			name:  "command display preserves literal escapes around a mask",
+			lines: "##[command]alpha tail%3Bvalue%5D",
+			masks: []string{"alpha"},
+			want:  "##[command]*** tail%3Bvalue%5D",
+		},
+		{
+			name:  "unknown modern commands preserve literal escapes",
+			lines: "::unknown::alpha tail%25value",
+			masks: []string{"alpha"},
+			want:  "::unknown::*** tail%25value",
+		},
+		{
+			name:  "masks can span command headers and data",
+			lines: "::group::hidden other",
+			masks: []string{"group::hidden", "other"},
+			want:  "::*** ***",
+		},
 	}
 	for _, entry := range table {
 		t.Run(entry.name, func(t *testing.T) {
@@ -56,6 +111,9 @@ func TestValueMasker(t *testing.T) {
 			masker := valueMasker(false, AppendSecretMaskers(nil, entry.secrets))
 			for line := range strings.SplitSeq(entry.lines, "\n") {
 				lentry := masker(ctx, logging.Record{Message: line})
+				if entry.want != "" {
+					assert.Equal(t, entry.want, lentry.Message)
+				}
 				for _, line := range entry.disallowed {
 					assert.NotContains(t, lentry.Message, line)
 				}
@@ -139,6 +197,7 @@ func TestValueMaskerEncodedMasks(t *testing.T) {
 		{"encoded: " + base64.StdEncoding.EncodeToString([]byte(" s3cr3t ")), "encoded: ***"},
 		{"encoded: " + base64.StdEncoding.EncodeToString([]byte("s3cr3t")), "encoded: ***"},
 		{"encoded: " + base64.StdEncoding.EncodeToString([]byte("first")), "encoded: ***"},
+		{"##[group]s3cr3t value\r\n", "##[group]***\r\n"},
 	} {
 		entry := masker(WithMasks(t.Context(), &masks), logging.Record{Message: tc.line})
 		assert.Equal(t, tc.want, entry.Message, tc.line)
@@ -194,17 +253,15 @@ func TestValueMaskerCachedReplacerSeesNewMasks(t *testing.T) {
 }
 
 func TestAppendSecretMaskerSkipsUselessEncodings(t *testing.T) {
-	// A token with no character an escape would touch only gains its base64 forms:
-	// JSON, query and path escaping all leave it unchanged.
 	pairs := AppendSecretMasker(nil, "plaintoken")
 	assert.Equal(t, []string{
 		"plaintoken", "***", "cGxhaW50b2tlbg==", "***", "bGFpbnRva2Vu", "***", "YWludG9rZW4=", "***",
 		"aW50b2tl", "***", "YWludG9r", "***", "bGFpbnRv", "***",
 	}, pairs)
 
-	// Too short to mask.
+	assert.Contains(t, AppendSecretMasker(nil, "x"), "x")
-	assert.Empty(t, AppendSecretMasker(nil, "x"))
 	assert.Empty(t, AppendSecretMasker(nil, " \t"))
+	assert.NotContains(t, AppendSecretMasker(nil, "{\nvalue\n}"), "{")
 	assert.NotContains(t, AppendSecretMasker(nil, `"123456"`), "123456")
 }
 

internal/pkg/report/reporter.go

@@ -960,7 +960,7 @@ func logRow(entry logging.Record) *runnerv1.LogRow {
 
 // mask repairs the content first, so a secret the repair itself spells out is still caught.
 func (r *Reporter) mask(content string) string {
-	return r.logReplacer.Replace(strings.ToValidUTF8(content, "?"))
+	return runner.MaskLog(strings.ToValidUTF8(content, "?"), r.logReplacer)
 }
 
 // AddMask deliberately leaves the process-wide masker alone. Its entries come from every live

internal/pkg/report/reporter_test.go

@@ -750,8 +750,7 @@ func TestReporter_ParseResult(t *testing.T) {
 func TestReporter_masksEncodedSecrets(t *testing.T) {
 	secret := `p@ss w"rd/1`
 	r := &Reporter{logReplacer: strings.NewReplacer()}
-	r.oldnew = runner.AppendSecretMasker(r.oldnew, secret)
+	r.AddMask(secret)
-	r.logReplacer = strings.NewReplacer(r.oldnew...)
 
 	for _, line := range []string{
 		"token: " + secret,
@@ -763,6 +762,17 @@ func TestReporter_masksEncodedSecrets(t *testing.T) {
 		assert.NotContains(t, masked, secret)
 		assert.NotContains(t, masked, base64.StdEncoding.EncodeToString([]byte(secret)))
 	}
+
+	r.AddMask("alpha beta;gamma]delta")
+	r.AddMask("%")
+	for _, test := range []struct{ line, want string }{
+		{"##[group]alpha beta%3Bgamma%5Ddelta", "##[group]***"},
+		{"##[group]alpha beta%3Bgamma]delta", "##[group]***"},
+		{"%", "***"},
+	} {
+		r.appendLogRow(logRow(logging.Record{Message: test.line}))
+		assert.Equal(t, test.want, r.logRows[len(r.logRows)-1].Content)
+	}
 }
 
 func TestReporter_AckIndexBeyondBuffer(t *testing.T) {