From 430f7bb2cf708cad13d4eae36845e2fc539a152e Mon Sep 17 00:00:00 2001 From: silverwind Date: Wed, 21 Oct 2026 16:03:40 +0000 Subject: [PATCH] fix: handle workflow commands like GitHub's runner (#1333) Commands the runner applies itself, like the `::set-output::` older actions still print, showed up raw in the job log. The reporter also re-parsed every line with one job-wide stop-commands and echo state, while act keeps one command handler per step, stage, composite child and hook, as GitHub does. A `::stop-commands::` left active in one of them kept the reporter suppressed for the others, so their `::add-mask::` values were never registered, and post steps logged command lines twice. - act's command handler decides what reaches the log, as GitHub's runner does: applied commands only under `ACTIONS_STEP_DEBUG` or `::echo::on`, `::stop-commands::` and its resume line shown with long tokens masked - Masks go straight to the reporter, which no longer parses command lines - One parser follows GitHub's rules: leading whitespace, `##[...]` anywhere in a line, registered commands only - Service logs honour only `::add-mask::` --------- Co-authored-by: bircni Reviewed-on: https://gitea.com/gitea/runner/pulls/1333 Reviewed-by: bircni Co-authored-by: silverwind --- DEVELOPMENT.md | 4 +- act/runner/action_composite.go | 9 +- act/runner/command.go | 196 +++++++------ act/runner/command_test.go | 379 ++++++++++++------------- act/runner/job_executor.go | 13 +- act/runner/job_hooks.go | 2 +- act/runner/job_hooks_test.go | 26 ++ act/runner/logger.go | 2 +- act/runner/run_context.go | 19 +- act/runner/run_context_test.go | 2 +- act/runner/runner.go | 4 +- internal/pkg/report/globalmask_test.go | 9 +- internal/pkg/report/joblog_test.go | 5 +- internal/pkg/report/reporter.go | 167 ++--------- internal/pkg/report/reporter_test.go | 266 +---------------- 15 files changed, 374 insertions(+), 729 deletions(-) diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index ecf0954f..17820e50 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -28,8 +28,8 @@ depending on the prefix: - **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 encoded forms too. -- Command *properties* also escape `%3A` and `%2C`, which the UI never decodes, so the reporter - decodes exactly those two when folding a location into an annotation. +- 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. ## Logging diff --git a/act/runner/action_composite.go b/act/runner/action_composite.go index 69ba5352..0181669e 100644 --- a/act/runner/action_composite.go +++ b/act/runner/action_composite.go @@ -241,14 +241,7 @@ func (rc *RunContext) compositeExecutor(action *model.Action) *compositeSteps { func (rc *RunContext) newCompositeCommandExecutor(executor common.Executor) common.Executor { return func(ctx context.Context) error { - ctx = WithCompositeLogger(ctx, &rc.Masks) - - logWriter := rc.commandLogWriter(ctx) - - oldout, olderr := rc.JobContainer.ReplaceLogWriter(logWriter, logWriter) - defer rc.JobContainer.ReplaceLogWriter(oldout, olderr) - - return executor(ctx) + return rc.withCommandLogWriter(WithCompositeLogger(ctx, &rc.Masks), executor) } } diff --git a/act/runner/command.go b/act/runner/command.go index 7c119a08..44248788 100644 --- a/act/runner/command.go +++ b/act/runner/command.go @@ -5,61 +5,72 @@ package runner import ( + "cmp" "context" "fmt" - "regexp" "strings" + "unicode" "gitea.com/gitea/runner/act/common" ) -var commandPatternGA *regexp.Regexp - -var commandPatternADO *regexp.Regexp - -func init() { - commandPatternGA = regexp.MustCompile("^::([^ ]+?)( (.+?))?::([^\r\n]*)[\r\n]*$") - // excluding ']' ends the command info at the first bracket, as GitHub does - commandPatternADO = regexp.MustCompile("^##\\[([^ \\]]+)( ([^\\]]*))?]([^\r\n]*)[\r\n]*$") -} - -func tryParseRawActionCommand(line string) (command string, kvPairs map[string]string, arg string, ok bool) { - command, kvPairs, arg, _, ok = tryParseActionCommand(line) - return command, kvPairs, arg, ok -} - -func tryParseActionCommand(line string) (command string, kvPairs map[string]string, arg string, legacy, ok bool) { - if m := commandPatternGA.FindStringSubmatch(line); m != nil { - command = m[1] - kvPairs = parseKeyValuePairs(m[3], ",") - arg = m[4] - ok = true - } else if m := commandPatternADO.FindStringSubmatch(line); m != nil { - command = m[1] - kvPairs = parseKeyValuePairs(m[3], ";") - arg = m[4] - legacy = true - ok = true +// parseActionCommand parses like GitHub's runner, but rejects a bare \r GitHub would split at and keeps a value's leading '=' so masks match. +func parseActionCommand(line, resumeCommand string) (command string, properties map[string]string, data string, legacy, ok bool) { + line = strings.TrimRight(line, "\r\n") + if strings.ContainsAny(line, "\r\n") { + return "", nil, "", false, false } - return command, kvPairs, arg, legacy, ok + trimmed := strings.TrimLeftFunc(line, unicode.IsSpace) + for _, legacy := range []bool{false, true} { + header, found := strings.CutPrefix(trimmed, "::") + separator, propertySeparator, unescapeProperty, unescapeData := "::", ",", commandPropertyUnescaper.Replace, UnescapeCommandData + if legacy { + _, header, found = strings.Cut(line, "##[") + separator, propertySeparator, unescapeProperty, unescapeData = "]", ";", UnescapeLegacyCommand, UnescapeLegacyCommand + } + if !found { + continue + } + header, data, found := strings.Cut(header, separator) + if !found { + continue + } + command, propertyList, _ := strings.Cut(header, " ") + command = strings.ToLower(command) + switch command { + case "stop-commands", "set-env", "set-output", "save-state", "add-path", "add-mask", "add-matcher", + "remove-matcher", "warning", "error", "notice", "debug", "group", "endgroup", "echo": + default: + if resumeCommand == "" || !strings.EqualFold(command, resumeCommand) { + continue + } + } + if !legacy { + propertyList = strings.TrimSpace(propertyList) + } + properties := map[string]string{} + for property := range strings.SplitSeq(propertyList, propertySeparator) { + if key, value, _ := strings.Cut(strings.TrimLeft(property, "="), "="); value != "" { + properties[strings.ToLower(key)] = unescapeProperty(value) + } + } + return command, properties, unescapeData(data), legacy, true + } + return "", nil, "", false, false } +// commandHandler reports whether a line is logged, keeping per-handler command state as GitHub does. func (rc *RunContext) commandHandler(ctx context.Context) common.LineHandler { - logger := common.Logger(ctx) + rawLogger := common.Logger(ctx).With(rawOutputField, true) + debug := rc.topLevelRunContext().Config.RunnerDebug() + echo := debug resumeCommand := "" return func(line string) bool { - command, kvPairs, arg, legacy, ok := tryParseActionCommand(line) + command, kvPairs, arg, _, ok := parseActionCommand(line, resumeCommand) if !ok { return true } - command = strings.ToLower(command) - if resumeCommand != "" { - // There should not be any emojis in the log output for Gitea. - // Return true (not false) so the line still reaches the raw_output - // log handler; otherwise everything between ::stop-commands:: and - // its end token is silently dropped from the step log. - logger.Infof("%s", line) // Resumed here rather than from the switch, because the end token is arbitrary // and a token naming a real command would otherwise never resume. if strings.EqualFold(command, resumeCommand) { @@ -67,15 +78,9 @@ func (rc *RunContext) commandHandler(ctx context.Context) common.LineHandler { } return true } - if legacy { - arg = UnescapeLegacyCommand(arg) - kvPairs = unescapeKvPairs(kvPairs, UnescapeLegacyCommand) - } else { - arg = UnescapeCommandData(arg) - kvPairs = unescapeKvPairs(kvPairs, unescapeCommandProperty) - } + echoed := echo if (command == "set-env" || command == "add-path") && rc.refuseUnsecureCommand(ctx, command) { - return true + return echoed } switch command { case "set-env": @@ -83,26 +88,67 @@ func (rc *RunContext) commandHandler(ctx context.Context) common.LineHandler { case "set-output": rc.setOutput(ctx, kvPairs, arg) case "add-path": - rc.addPath(ctx, arg) + rc.addPath(arg) + case "save-state": + rc.saveState(ctx, kvPairs, arg) + case "echo": + switch strings.ToLower(strings.TrimSpace(arg)) { + case "on": + echo = true + case "off": + echo = false + } case "add-mask": - rc.AddMask(arg) - logger.Infof("%s", "***") - // The raw line is still forwarded, carrying the secret: that is how the reporter - // learns the mask, and it drops the row rather than writing it out. + rc.AddMask(ctx, arg) + if echoed { + rawLogger.Infof("::add-mask::***") + } + return false case "stop-commands": resumeCommand = arg - logger.Infof("%s", line) - case "save-state": - logger.Infof("%s", line) - rc.saveState(ctx, kvPairs, arg) - default: - // ::debug::, ::error::, ::warning::, ::add-matcher:: and anything unrecognised are - // passed through for the reporter and Gitea's web UI to render. - logger.Infof("%s", line) + if len(arg) > 6 { // as on GitHub, so the log does not give away the resume token + rc.AddMask(ctx, arg) + } + return true + case "debug": + return debug + case "notice", "warning", "error": + rawLogger.Infof("%s", formatAnnotation(command, kvPairs, arg)) + return false + case "group", "endgroup": + return true } + return echoed + } +} - // return true to let gitea's logger handle these special outputs also - return true +// formatAnnotation folds the location and title into the message, as Gitea's web UI drops command properties. +func formatAnnotation(level string, properties map[string]string, message string) string { + prefix := properties["file"] + if prefix != "" { + if line := properties["line"]; line != "" { + prefix += ":" + line + if col := cmp.Or(properties["col"], properties["column"]); col != "" { + prefix += ":" + col + } + } + prefix += ": " + } + if title := properties["title"]; title != "" { + prefix += title + ": " + } + return "::" + level + "::" + EscapeCommandData(prefix+message) +} + +// serviceCommandHandler applies only ::add-mask::, so a service cannot set the job's env, outputs or state. +func (rc *RunContext) serviceCommandHandler(ctx context.Context) common.LineHandler { + return func(line string) bool { + command, _, arg, _, ok := parseActionCommand(line, "") + if !ok || command != "add-mask" { + return true + } + rc.AddMask(ctx, arg) + return false } } @@ -162,7 +208,6 @@ func (rc *RunContext) setEnv(ctx context.Context, kvPairs map[string]string, arg common.Logger(ctx).With(rawOutputField, true).Errorf("##[error]%s", EscapeCommandData(message)) return } - common.Logger(ctx).Infof("::set-env:: %s=%s", name, arg) if rc.Env == nil { rc.Env = make(map[string]string) } @@ -195,12 +240,10 @@ func (rc *RunContext) setOutput(ctx context.Context, kvPairs map[string]string, return } - logger.Infof("::set-output:: %s=%s", outputName, arg) result.Outputs[outputName] = arg } -func (rc *RunContext) addPath(ctx context.Context, arg string) { - common.Logger(ctx).Infof("::add-path:: %s", arg) +func (rc *RunContext) addPath(arg string) { extraPath := []string{arg} for _, v := range rc.ExtraPath { if v != arg { @@ -210,18 +253,6 @@ func (rc *RunContext) addPath(ctx context.Context, arg string) { rc.ExtraPath = extraPath } -func parseKeyValuePairs(kvPairs, separator string) map[string]string { - rtn := make(map[string]string) - kvPairList := strings.SplitSeq(kvPairs, separator) - for kvPair := range kvPairList { - kv := strings.SplitN(kvPair, "=", 2) - if len(kv) == 2 { - rtn[kv[0]] = kv[1] - } - } - return rtn -} - // A Replacer never rescans what it wrote, so "%250A" stays a literal "%0A". var ( commandDataEscaper = strings.NewReplacer("%", "%25", "\r", "%0D", "\n", "%0A") @@ -240,22 +271,11 @@ func UnescapeCommandData(arg string) string { return commandDataUnescaper.Replace(arg) } -func unescapeCommandProperty(arg string) string { - return commandPropertyUnescaper.Replace(arg) -} - // UnescapeLegacyCommand decodes a "##[cmd]" line, which also spells ";" and "]" escaped. func UnescapeLegacyCommand(arg string) string { return legacyCommandUnescaper.Replace(arg) } -func unescapeKvPairs(kvPairs map[string]string, unescape func(string) string) map[string]string { - for k, v := range kvPairs { - kvPairs[k] = unescape(v) - } - return kvPairs -} - func (rc *RunContext) saveState(_ context.Context, kvPairs map[string]string, arg string) { stepID := rc.CurrentStep if stepID != "" { diff --git a/act/runner/command_test.go b/act/runner/command_test.go index 3486ce5c..0e627cd2 100644 --- a/act/runner/command_test.go +++ b/act/runner/command_test.go @@ -5,12 +5,13 @@ package runner import ( - "bytes" "io" - "os" + "strconv" + "strings" "testing" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.dev/actionslib/pkg/model" @@ -18,9 +19,56 @@ import ( "github.com/stretchr/testify/require" ) +func TestParseActionCommand(t *testing.T) { + for _, test := range []struct { + name, line, resumeCommand, command string + properties map[string]string + data string + legacy, ok bool + }{ + {"plain", "plain output", "", "", nil, "", false, false}, + {"unknown v2", "::unknown::v", "", "", nil, "", false, false}, + {"missing v2 terminator", "::set-output name=x", "", "", nil, "", false, false}, + {"empty command", "::::", "", "", nil, "", false, false}, + {"text before v2", "debug ::set-output name=x::v", "", "", nil, "", false, false}, + {"missing legacy terminator", "##[debug", "", "", nil, "", false, false}, + {"tab is not a name separator", "::set-output\tname=x::v", "", "", nil, "", false, false}, + {"v2 leading unicode whitespace and line endings", " \t\u2003::set-output name=tab::v\r\n\r\n", "", "set-output", map[string]string{"name": "tab"}, "v", false, true}, + {"legacy prefix and casing", "prefix ##[SET-OUTPUT NAME=mid;]v\r\n", "", "set-output", map[string]string{"name": "mid"}, "v", true, true}, + {"only first legacy prefix", "##[unknown]##[set-output name=x]v", "", "", nil, "", false, false}, + {"v2 delimiter boundaries", "::set-output name=a:b,other=c:d:: a::b ", "", "set-output", map[string]string{"name": "a:b", "other": "c:d"}, " a::b ", false, true}, + {"legacy first closing bracket", "##[set-output name=x]v]tail", "", "set-output", map[string]string{"name": "x"}, "v]tail", true, true}, + {"v2 semicolons are literal", "::set-output name=x;y=z::v", "", "set-output", map[string]string{"name": "x;y=z"}, "v", false, true}, + {"legacy commas are literal", "##[set-output name=x,y=z]v", "", "set-output", map[string]string{"name": "x,y=z"}, "v", true, true}, + {"values keep their leading equals", "::set-output name==x=y,=key=v,empty=,=x,spaced= =x::v", "", "set-output", map[string]string{"name": "=x=y", "key": "v", "spaced": " =x"}, "v", false, true}, + {"v2 trims whole list only", "::set-output \tfile=x, line=2,name = value \t::v", "", "set-output", map[string]string{"file": "x", " line": "2", "name ": " value"}, "v", false, true}, + {"legacy preserves list whitespace", "##[set-output name=q ]v", "", "set-output", map[string]string{" name": "q "}, "v", true, true}, + {"case insensitive duplicate keys", "::SET-OUTPUT NAME=first,Name=last::v", "", "set-output", map[string]string{"name": "last"}, "v", false, true}, + {"keys stay escaped", "::set-output na%3Ame=x::v", "", "set-output", map[string]string{"na%3ame": "x"}, "v", false, true}, + {"v2 decode table", "::set-output name=%0D%0A%3A%2C%25%253A%252C%250A%2525%3a%2c%0d%0a%3B%5D::%0D%0A%25%3A%2C%3B%5D%250A", "", "set-output", map[string]string{"name": "\r\n:,%%3A%2C%0A%25%3a%2c%0d%0a%3B%5D"}, "\r\n%%3A%2C%3B%5D%0A", false, true}, + {"legacy decode table", "##[set-output name=%3B%0D%0A%5D%25%253B%255D%250A%2525%3b%5d%0d%0a%3A%2C]v%5Dw%3Bx", "", "set-output", map[string]string{"name": ";\r\n]%%3B%5D%0A%25%3b%5d%0d%0a%3A%2C"}, "v]w;x", true, true}, + {"unknown v2 falls back to legacy", "::unknown::prefix ##[set-output name=x]v", "", "set-output", map[string]string{"name": "x"}, "v", true, true}, + {"unterminated v2 falls back to legacy", "::debug ##[set-output name=x]v", "", "set-output", map[string]string{"name": "x"}, "v", true, true}, + {"v2 wins over legacy", "::debug::##[set-output name=x]v", "", "debug", map[string]string{}, "##[set-output name=x]v", false, true}, + {"internal line breaks are not commands", "::debug::hidden\rplain\r\n", "", "", nil, "", false, false}, + {"v2 resume token", "::ReSuMe-ToKeN::", "RESUME-TOKEN", "resume-token", map[string]string{}, "", false, true}, + {"legacy resume token", "prefix ##[RESUME-TOKEN]v", "resume-token", "resume-token", map[string]string{}, "v", true, true}, + {"different resume token", "::other-token::", "resume-token", "", nil, "", false, false}, + } { + t.Run(test.name, func(t *testing.T) { + command, properties, data, legacy, ok := parseActionCommand(test.line, test.resumeCommand) + assert.Equal(t, test.command, command) + assert.Equal(t, test.properties, properties) + assert.Equal(t, test.data, data) + assert.Equal(t, test.legacy, legacy) + assert.Equal(t, test.ok, ok) + }) + } +} + // unsecureRC opts into ::set-env:: and ::add-path::, which are refused without it. func unsecureRC() *RunContext { - return &RunContext{Env: map[string]string{allowUnsecureCommandsVar: "true"}} + return &RunContext{Config: &Config{}, Env: map[string]string{allowUnsecureCommandsVar: "true"}} } func TestSetEnv(t *testing.T) { @@ -37,212 +85,37 @@ func TestSetEnv(t *testing.T) { a.NotContains(rc.Env, "NODE_OPTIONS") a.NotContains(rc.Env, "node_options") entries := hook.AllRecords() - require.Len(t, entries, 3) - a.Equal("##[error]Can't update NODE_OPTIONS environment variable using ::set-env:: command.", entries[1].Message) - a.Equal("##[error]Can't store NODE_OPTIONS output parameter using '$GITHUB_ENV' command.", entries[2].Message) -} - -func TestStopCommandsKeepsSuppressedLinesInLog(t *testing.T) { - a := assert.New(t) - ctx := t.Context() - rc := unsecureRC() - handler := rc.commandHandler(ctx) - - // Stop command processing until the matching end token is seen. - a.True(handler("::stop-commands::my-end-token\n")) - - // A command-shaped line while stopped must not be executed (env unchanged), - // but must still return true so it reaches the raw_output log handler and is - // not dropped from the step log. - a.True(handler("::set-env name=x::valz\n")) - a.NotContains(rc.Env, "x") - - // The matching end token resumes command processing. - a.True(handler("::my-end-token::\n")) - - // Commands are processed again after resuming. - a.True(handler("::set-env name=y::valy\n")) - a.Equal("valy", rc.Env["y"]) + require.Len(t, entries, 2) + a.Equal("##[error]Can't update NODE_OPTIONS environment variable using ::set-env:: command.", entries[0].Message) + a.Equal("##[error]Can't store NODE_OPTIONS output parameter using '$GITHUB_ENV' command.", entries[1].Message) } func TestSetOutput(t *testing.T) { - a := assert.New(t) - ctx := t.Context() - rc := new(RunContext) - rc.StepResults = make(map[string]*model.StepResult) - handler := rc.commandHandler(ctx) + rc := &RunContext{Config: &Config{}, CurrentStep: "my-step", StepResults: map[string]*model.StepResult{"my-step": {Outputs: map[string]string{}}}} + handler := rc.commandHandler(t.Context()) - rc.CurrentStep = "my-step" - rc.StepResults[rc.CurrentStep] = &model.StepResult{ - Outputs: make(map[string]string), - } - handler("::set-output name=x::valz\n") - a.Equal("valz", rc.StepResults["my-step"].Outputs["x"]) - - handler("::set-output name=x::percent2%25\n") - a.Equal("percent2%", rc.StepResults["my-step"].Outputs["x"]) - - handler("::set-output name=x::percent2%25%0Atest\n") - a.Equal("percent2%\ntest", rc.StepResults["my-step"].Outputs["x"]) - - handler("::set-output name=x::percent2%25%0Atest another3%25test\n") - a.Equal("percent2%\ntest another3%test", rc.StepResults["my-step"].Outputs["x"]) - - handler("::set-output name=x%3A::percent2%25%0Atest\n") - a.Equal("percent2%\ntest", rc.StepResults["my-step"].Outputs["x:"]) - - handler("::set-output name=x%3A%2C%0A%25%0D%3A::percent2%25%0Atest\n") - a.Equal("percent2%\ntest", rc.StepResults["my-step"].Outputs["x:,\n%\r:"]) - handler("::set-output name=symbol::std::vector") - a.Equal("std::vector", rc.StepResults["my-step"].Outputs["symbol"]) - handler("::set-output name=a=b::value\n") - a.Equal("value", rc.StepResults["my-step"].Outputs["a=b"]) - handler("##[set-output name=legacy%3B%5D]value%3B%5D") - a.Equal("value;]", rc.StepResults["my-step"].Outputs["legacy;]"]) - handler("##[set-output name=bracket]value]tail") - a.Equal("value]tail", rc.StepResults["my-step"].Outputs["bracket"]) - handler("::set-output name=modern%3B%5D::value%3B%5D\n") - a.Equal("value%3B%5D", rc.StepResults["my-step"].Outputs["modern%3B%5D"]) + handler("::set-output NAME=modern%3A::v%0D%0A%25%3B%5D%250A\n") + handler("##[set-output name=legacy%3B%5D]v%0D%0A%25%3B%5D%250A\n") + assert.Equal(t, map[string]string{"modern:": "v\r\n%%3B%5D%0A", "legacy;]": "v\r\n%;]%0A"}, rc.StepResults["my-step"].Outputs) } func TestAddpath(t *testing.T) { - a := assert.New(t) - ctx := t.Context() - rc := unsecureRC() - handler := rc.commandHandler(ctx) - - handler("::add-path::/zoo\n") - a.Equal("/zoo", rc.ExtraPath[0]) - - handler("::add-path::/boo\n") - a.Equal("/boo", rc.ExtraPath[0]) -} - -func TestStopCommands(t *testing.T) { - logger, hook := logtest.NewLogger() - - a := assert.New(t) - ctx := common.WithLogger(t.Context(), logger) - rc := unsecureRC() - handler := rc.commandHandler(ctx) - - handler("::set-env name=x::valz\n") - a.Equal("valz", rc.Env["x"]) - handler("::stop-commands::MY-END-TOKEN\n") - handler("::set-env name=x::abcd\n") - a.Equal("valz", rc.Env["x"]) - handler("::my-end-token::\n") - handler("::set-env name=x::abcd\n") - a.Equal("abcd", rc.Env["x"]) - - messages := make([]string, 0) - for _, entry := range hook.AllRecords() { - messages = append(messages, entry.Message) + for _, prefix := range []string{"::add-path::", "##[add-path]"} { + t.Run(prefix, func(t *testing.T) { + rc := unsecureRC() + handler := rc.commandHandler(t.Context()) + handler(prefix + "/zoo\n") + handler(prefix + "/boo\n") + assert.Equal(t, []string{"/boo", "/zoo"}, rc.ExtraPath) + handler(prefix + "/zoo\n") + assert.Equal(t, []string{"/zoo", "/boo"}, rc.ExtraPath) + }) } - - a.Contains(messages, "::set-env name=x::abcd\n") -} - -// The end token is arbitrary, so one that happens to name a real command must still resume -// rather than being swallowed by that command's case. -func TestStopCommandsResumesOnCommandNamedToken(t *testing.T) { - a := assert.New(t) - rc := unsecureRC() - handler := rc.commandHandler(t.Context()) - - handler("::stop-commands::add-mask\n") - handler("::set-env name=x::suppressed\n") - a.NotContains(rc.Env, "x") - - handler("::add-mask::\n") - handler("::set-env name=x::resumed\n") - a.Equal("resumed", rc.Env["x"]) -} - -func TestAddpathADO(t *testing.T) { - a := assert.New(t) - ctx := t.Context() - rc := unsecureRC() - handler := rc.commandHandler(ctx) - - handler("##[add-path]/zoo\n") - a.Equal("/zoo", rc.ExtraPath[0]) - - handler("##[add-path]/boo\n") - a.Equal("/boo", rc.ExtraPath[0]) -} - -func TestAddmask(t *testing.T) { - logger, hook := logtest.NewLogger() - - a := assert.New(t) - ctx := t.Context() - loggerCtx := common.WithLogger(ctx, logger) - - rc := new(RunContext) - handler := rc.commandHandler(loggerCtx) - handler("::ADD-MASK::my::secret") - - a.Equal("***", hook.LastRecord().Message) - a.Equal([]string{"my::secret"}, rc.Masks) -} - -// based on https://stackoverflow.com/a/10476304 -func captureOutput(t *testing.T, f func()) string { - old := os.Stdout - r, w, _ := os.Pipe() - os.Stdout = w - - f() - - outC := make(chan string) - - go func() { - var buf bytes.Buffer - _, err := io.Copy(&buf, r) - if err != nil { - a := assert.New(t) - a.Fail("io.Copy failed") - } - outC <- buf.String() - }() - - w.Close() - os.Stdout = old - out := <-outC - - return out -} - -func TestAddmaskUsemask(t *testing.T) { - rc := new(RunContext) - rc.StepResults = make(map[string]*model.StepResult) - rc.CurrentStep = "my-step" - rc.StepResults[rc.CurrentStep] = &model.StepResult{ - Outputs: make(map[string]string), - } - - a := assert.New(t) - - config := &Config{ - Secrets: map[string]string{}, - InsecureSecrets: false, - } - - re := captureOutput(t, func() { - ctx := t.Context() - ctx = WithJobLogger(ctx, "0", "testjob", config, &rc.Masks, map[string]any{}) - - handler := rc.commandHandler(ctx) - handler("::add-mask::secret\n") - handler("::set-output:: token=secret\n") - }) - - a.Equal("[testjob] ***\n[testjob] ::set-output:: = token=***\n", re) } func TestSaveState(t *testing.T) { rc := &RunContext{ + Config: &Config{}, CurrentStep: "step", StepResults: map[string]*model.StepResult{}, } @@ -278,12 +151,12 @@ func TestUnsecureCommands(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { a := assert.New(t) - rc := &RunContext{Env: tt.jobEnv} + rc := &RunContext{Config: &Config{}, Env: tt.jobEnv} rc.setCurrentStepEnv(tt.stepEnv) handler := rc.commandHandler(t.Context()) - handler("::set-env name=x::valz\n") - handler("::add-path::/opt/bin\n") + a.False(handler("::set-env name=x::valz\n")) + a.False(handler("::add-path::/opt/bin\n")) if !tt.optedIn { a.Empty(rc.Env["x"]) @@ -299,3 +172,109 @@ func TestUnsecureCommands(t *testing.T) { }) } } + +type maskRecorder struct { + logging.Handler + masks []string +} + +func (m *maskRecorder) AddMask(mask string) { m.masks = append(m.masks, mask) } + +func TestCommandLogWriter(t *testing.T) { + for _, tt := range []struct { + name string + debug bool + steps [][]string + log []string + masks []string + }{ + { + name: "applied commands are hidden unless echoed", + steps: [][]string{{ + "::set-env name=x::y", "::add-path::/bin", "::set-output name=a::b", "##[save-state name=a]b", "::add-matcher::m.json", "::remove-matcher owner=m::", + "::echo::On%0A", + "::set-env name=x::y", "::add-path::/bin", "::set-output name=a::b", "##[save-state name=a]b", "::add-matcher::m.json", "::remove-matcher owner=m::", + "::ADD-MASK::my::secret", "::echo::bogus", "::echo::off", "::add-mask ::empty-properties", "::unknown::v", "plain", + }}, + log: []string{ + "::set-env name=x::y", "::add-path::/bin", "::set-output name=a::b", "##[save-state name=a]b", "::add-matcher::m.json", "::remove-matcher owner=m::", + "::add-mask::***", "::echo::bogus", "::echo::off", "::unknown::v", "plain", + }, + masks: []string{"my::secret", "empty-properties"}, + }, + { + name: "step debug shows debug lines and echoes commands until echo is off", + debug: true, + steps: [][]string{{"::debug::first%0Asecond", "::set-output name=a::b", "::echo::off", "::debug::again", "::set-output name=a::b"}}, + log: []string{"::debug::first%0Asecond", "::set-output name=a::b", "::echo::off", "::debug::again"}, + }, + { + name: "debug lines are hidden without step debug and an invalid echo changes nothing", + steps: [][]string{{"::echo::bogus", "::set-output name=a::b", "::echo::on", "::debug::d"}}, + }, + { + name: "annotations fold their location once whether echoed or not", + steps: [][]string{{ + "::echo::on", + "::error file=main.go,line=12,col=5,title=vet::undefined: x", + "::warning File=a%3Ab.go,Line=1,column=2,title=100%252C::50%25%0Anext", + "::warning file=x,line=1,col=2,column=3::m", + "::notice line=9,col=4,title=title::m", + "::error file=x,col=2::m", + "::error file=x,line=1::m", + "::notice::std::vector", + "##[error file=x%3By]m%5D", + }}, + log: []string{ + "::error::main.go:12:5: vet: undefined: x", "::warning::a:b.go:1:2: 100%252C: 50%25%0Anext", "::warning::x:1:2: m", + "::notice::title: m", "::error::x: m", "::error::x:1: m", "::notice::std::vector", "::error::x;y: m]", + }, + }, + { + name: "stop-commands keeps lines verbatim until resumed", + steps: [][]string{{"::stop-commands::resume-token", "::add-mask::kept", "::set-output name=a::b", "::RESUME-TOKEN::", "::add-mask::masked"}}, + log: []string{"::stop-commands::resume-token", "::add-mask::kept", "::set-output name=a::b", "::RESUME-TOKEN::"}, + masks: []string{"resume-token", "masked"}, + }, + { + name: "a short stop token naming a command stays unmasked and resumes in any case", + steps: [][]string{{"::stop-commands::NOTICE", "::notice::", "::add-mask::masked"}}, + log: []string{"::stop-commands::NOTICE", "::notice::"}, + masks: []string{"masked"}, + }, + { + name: "state does not carry over to the next step", + steps: [][]string{{"::echo::on", "::stop-commands::token77"}, {"::set-output name=a::b", "::add-mask::masked"}}, + log: []string{"::stop-commands::token77"}, + masks: []string{"token77", "masked"}, + }, + } { + t.Run(tt.name, func(t *testing.T) { + logger, hook := logtest.NewLogger() + recorder := &maskRecorder{} + ctx := common.WithLoggerHandler(common.WithLogger(t.Context(), logger), recorder) + rc := &RunContext{ + Config: &Config{}, + Parent: &RunContext{Config: &Config{Secrets: map[string]string{"ACTIONS_STEP_DEBUG": strconv.FormatBool(tt.debug)}}}, + Env: map[string]string{allowUnsecureCommandsVar: "true"}, + CurrentStep: "step", + StepResults: map[string]*model.StepResult{"step": {Outputs: map[string]string{}}}, + } + for _, lines := range tt.steps { + writer := rc.commandLogWriter(ctx) + for _, line := range lines { + _, err := io.WriteString(writer, line+"\n") + require.NoError(t, err) + } + } + + var log []string + for _, record := range hook.AllRecords() { + log = append(log, strings.TrimSuffix(record.Message, "\n")) + } + assert.Equal(t, tt.log, log) + assert.Equal(t, tt.masks, recorder.masks) + assert.Equal(t, tt.masks, rc.Masks) + }) + } +} diff --git a/act/runner/job_executor.go b/act/runner/job_executor.go index 69accaa9..6a3c63d7 100644 --- a/act/runner/job_executor.go +++ b/act/runner/job_executor.go @@ -732,17 +732,6 @@ func useJobStageLogger(stage string, executor common.Executor) common.Executor { func useStepLogger(rc *RunContext, stepModel *model.Step, stage stepStage, executor common.Executor) common.Executor { return func(ctx context.Context) error { ctx = withStepLogger(ctx, stepModel.Number, stepModel.ID, rc.ExprEval.InterpolateName(ctx, stepModel.String()), stage.String()) - - logWriter := rc.commandLogWriter(ctx) - - oldout, olderr := rc.JobContainer.ReplaceLogWriter(logWriter, logWriter) - defer rc.JobContainer.ReplaceLogWriter(oldout, olderr) - - // Flush any buffered, not-yet-newline-terminated trailing line once the - // step has finished, so the final line of the step's output is not lost - // when it is not newline-terminated. - defer common.FlushWriter(logWriter) - - return executor(ctx) + return rc.withCommandLogWriter(ctx, executor) } } diff --git a/act/runner/job_hooks.go b/act/runner/job_hooks.go index 26f30b1f..b074898a 100644 --- a/act/runner/job_hooks.go +++ b/act/runner/job_hooks.go @@ -56,7 +56,7 @@ func (rc *RunContext) runJobHook(ctx context.Context, hookPath, name string) err err := rc.setupHookFileCommands(ctx, env) if err == nil { - err = rc.JobContainer.Exec(cmd, env, "", "")(ctx) + err = rc.withCommandLogWriter(ctx, rc.JobContainer.Exec(cmd, env, "", "")) } // Processed even on failure, so a hook that exports what it managed to set up before // failing still hands it to the job. diff --git a/act/runner/job_hooks_test.go b/act/runner/job_hooks_test.go index 046d675a..84b82e93 100644 --- a/act/runner/job_hooks_test.go +++ b/act/runner/job_hooks_test.go @@ -29,6 +29,8 @@ type hookContainer struct { err error envFile map[string]string pathTar []byte + output string + stdout io.Writer } func (c *hookContainer) ToContainerPath(path string) string { return path } @@ -41,10 +43,21 @@ func (c *hookContainer) GetRunnerContext(context.Context) map[string]any { func (c *hookContainer) Exec(command []string, env map[string]string, _, _ string) common.Executor { return func(context.Context) error { c.cmd, c.env = command, env + if c.output != "" { + if _, err := io.WriteString(c.stdout, c.output); err != nil { + return err + } + } return c.err } } +func (c *hookContainer) ReplaceLogWriter(stdout, _ io.Writer) (io.Writer, io.Writer) { + old := c.stdout + c.stdout = stdout + return old, nil +} + func (c *hookContainer) UpdateFromEnv(_ string, env *map[string]string) common.Executor { return func(context.Context) error { maps.Copy(*env, c.envFile) @@ -90,6 +103,19 @@ func TestRunJobHook(t *testing.T) { assert.Equal(t, "/var/run/act/workflow/hook-path.txt", jobContainer.env["GITHUB_PATH"]) }) + t.Run("each hook has its own command state", func(t *testing.T) { + jobContainer := &hookContainer{output: "::stop-commands::token77"} + rc, ctx := newHookRunContext(jobContainer, &Config{JobStartedHook: "/started.sh", JobCompletedHook: "/completed.sh"}) + jobWriter := rc.commandLogWriter(ctx) + jobContainer.stdout = jobWriter + + require.NoError(t, rc.runJobStartedHook(ctx)) + jobContainer.output = "::add-mask::s3cret" + require.NoError(t, rc.runJobCompletedHook(ctx)) + assert.Equal(t, []string{"token77", "s3cret"}, rc.Masks) + assert.Same(t, jobWriter, jobContainer.stdout) + }) + // Each hook reads its own variable, so a swapped constant cannot pass. t.Run("falls back to the GitHub environment variables", func(t *testing.T) { for name, hook := range map[string]struct { diff --git a/act/runner/logger.go b/act/runner/logger.go index 16a67526..a06c2efe 100644 --- a/act/runner/logger.go +++ b/act/runner/logger.go @@ -407,7 +407,7 @@ func (f textFormatter) format(r logging.Record) ([]byte, error) { b := &bytes.Buffer{} // the web renderer decodes command data, so this local view has to as well - if _, _, _, ok := tryParseRawActionCommand(r.Message + "\n"); ok { + if _, _, _, _, ok := parseActionCommand(r.Message, ""); ok && (strings.HasPrefix(r.Message, "::") || strings.HasPrefix(r.Message, "##[")) { r.Message = UnescapeCommandData(r.Message) } r.Message = strings.TrimSuffix(r.Message, "\n") diff --git a/act/runner/run_context.go b/act/runner/run_context.go index 6c7c903a..a920d688 100644 --- a/act/runner/run_context.go +++ b/act/runner/run_context.go @@ -164,8 +164,12 @@ func (rc *RunContext) markInterrupted(err error) { } } -func (rc *RunContext) AddMask(mask string) { +// AddMask also hands the mask to the job logger's extra handler, which receives records unmasked. +func (rc *RunContext) AddMask(ctx context.Context, mask string) { rc.Masks = append(rc.Masks, mask) + if masker, ok := common.LoggerHandler(ctx).(interface{ AddMask(string) }); ok { + masker.AddMask(mask) + } } func (rc *RunContext) String() string { @@ -672,7 +676,7 @@ func (rc *RunContext) jobServices(ctx context.Context, networkName string) (map[ return nil, fmt.Errorf("failed to parse service %s ports: %w", serviceID, err) } - serviceLog := common.NewLineWriter(rawLogLine(ctx)) // raw, so a service's output cannot set the job's env, outputs or state + serviceLog := common.NewLineWriter(rc.serviceCommandHandler(ctx), rawLogLine(ctx)) inputs[serviceID] = &container.NewContainerInput{ Name: createContainerName(rc.jobContainerName(), serviceID), Image: spec.Image, @@ -705,6 +709,15 @@ func (rc *RunContext) commandLogWriter(ctx context.Context) io.Writer { return common.NewLineWriter(rc.commandHandler(ctx), rawLogLine(ctx)) } +// withCommandLogWriter runs executor with a command handler of its own on the job environment's output. +func (rc *RunContext) withCommandLogWriter(ctx context.Context, executor common.Executor) error { + logWriter := rc.commandLogWriter(ctx) + oldout, olderr := rc.JobContainer.ReplaceLogWriter(logWriter, logWriter) + defer rc.JobContainer.ReplaceLogWriter(oldout, olderr) + defer common.FlushWriter(logWriter) // the last line of output may lack its newline + return executor(ctx) +} + func rawLogLine(ctx context.Context) common.LineHandler { rawLogger := common.Logger(ctx).With(rawOutputField, true) return func(line string) bool { @@ -853,7 +866,7 @@ func (rc *RunContext) UpdateExtraPath(ctx context.Context, githubEnvPath string) for s.Scan() { line := s.Text() if len(line) > 0 { - rc.addPath(ctx, line) + rc.addPath(line) } } if err := s.Err(); err != nil { diff --git a/act/runner/run_context_test.go b/act/runner/run_context_test.go index 3cada89d..e73a651c 100644 --- a/act/runner/run_context_test.go +++ b/act/runner/run_context_test.go @@ -1434,7 +1434,7 @@ func TestRunContext_cleanupFailedStart(t *testing.T) { slices.Sort(operations[:3]) slices.Sort(operations[len(operations)-4 : len(operations)-1]) assert.Equal(t, strings.Fields(want+" job.Remove service.Close service.Remove job.Close"), operations) - assert.Empty(t, rc.Masks) + assert.Equal(t, strings.Contains(want, "service.DumpLogs"), slices.Contains(rc.Masks, "leak")) assert.Equal(t, testcase.pullError == nil && testcase.health != container.HealthUnhealthy, slices.ContainsFunc(hook.AllRecords(), func(entry logging.Record) bool { return strings.HasPrefix(entry.Message, "::group::Print service container logs") })) diff --git a/act/runner/runner.go b/act/runner/runner.go index b85f4d12..5da3c922 100644 --- a/act/runner/runner.go +++ b/act/runner/runner.go @@ -94,9 +94,7 @@ type Config struct { JobCompletedHook string // script run inside the job environment after the job's last step; ACTIONS_RUNNER_HOOK_JOB_COMPLETED is read from Env when empty } -// RunnerDebug reports whether debug logging is on, exposed as `runner.debug` and -// RUNNER_DEBUG. Only the secret also makes the reporter keep ::debug:: output, the env -// is accepted for `exec` and for runners configured with it. +// RunnerDebug reports whether debug logging is on, exposed as `runner.debug` and RUNNER_DEBUG. func (c Config) RunnerDebug() bool { return c.Secrets["ACTIONS_STEP_DEBUG"] == "true" || c.Env["ACTIONS_STEP_DEBUG"] == "true" } diff --git a/internal/pkg/report/globalmask_test.go b/internal/pkg/report/globalmask_test.go index eb61b697..76708375 100644 --- a/internal/pkg/report/globalmask_test.go +++ b/internal/pkg/report/globalmask_test.go @@ -5,6 +5,7 @@ package report import ( "strings" + "sync" "testing" "gitea.com/gitea/runner/act/common/logging" @@ -53,7 +54,11 @@ func TestGlobalMasks(t *testing.T) { // A workflow could otherwise mask "error" here and rewrite every other task's log. third := register("s3cr3t", "***") - third.addMask("runtime-secret") + var writers sync.WaitGroup + for _, mask := range []string{"runtime-secret", "another-secret"} { + writers.Go(func() { third.AddMask(mask) }) + } + writers.Wait() assert.Contains(t, format("saw runtime-secret"), "runtime-secret") - assert.NotContains(t, third.mask("saw runtime-secret"), "runtime-secret") + assert.Equal(t, "saw *** ***", third.mask("saw runtime-secret another-secret")) } diff --git a/internal/pkg/report/joblog_test.go b/internal/pkg/report/joblog_test.go index 0bab3184..3abcebbe 100644 --- a/internal/pkg/report/joblog_test.go +++ b/internal/pkg/report/joblog_test.go @@ -59,9 +59,8 @@ func TestJobLog_MirrorsUploadedRows(t *testing.T) { })) } fire("the token is s3cret-value") - fire("::add-mask::dyn4mic-value") + reporter.AddMask("dyn4mic-value") fire("and dyn4mic-value too") - fire("::debug::suppressed unless ACTIONS_STEP_DEBUG") require.NoError(t, reporter.Close("")) job := readJobLog(t, reporter.jobLog) @@ -69,8 +68,6 @@ func TestJobLog_MirrorsUploadedRows(t *testing.T) { assert.Contains(t, job, "and *** too") assert.NotContains(t, job, "s3cret-value") assert.NotContains(t, job, "dyn4mic-value") - assert.NotContains(t, job, "add-mask", "the row carrying the secret never reaches the log") - assert.NotContains(t, job, "suppressed unless", "the file holds only what was sent") assert.NotRegexp(t, `(?m)^\S+Z ?$`, job, "the empty row Gitea needs is not job output") assert.Contains(t, job, "[runner] task 41 finished: failure") } diff --git a/internal/pkg/report/reporter.go b/internal/pkg/report/reporter.go index a4fbc738..89a4927e 100644 --- a/internal/pkg/report/reporter.go +++ b/internal/pkg/report/reporter.go @@ -9,7 +9,6 @@ import ( "errors" "fmt" "math/rand/v2" - "regexp" "slices" "strings" "sync" @@ -101,9 +100,6 @@ type Reporter struct { logNotify chan struct{} // signal: new log rows arrived stateNotify chan struct{} // signal: step transition (start/stop) - debugOutputEnabled bool - stopCommandEndToken string - jobLog *jobLog // this task's rows on the runner's own disk, nil when log.job.dir is unset } @@ -156,10 +152,6 @@ func NewReporter(ctx context.Context, cancel context.CancelFunc, client client.C registerGlobalMasks(rv) - if task.Secrets["ACTIONS_STEP_DEBUG"] == "true" { - rv.debugOutputEnabled = true - } - return rv } @@ -345,11 +337,8 @@ func (h *reporterHandler) WithAttrs(attrs []logging.Attr) logging.Handler { } // appendLogRow masks a row before buffering it for Gitea and the local job.log, the one point -// feeding both. A nil row is one the command handler dropped. Caller holds stateMu. +// feeding both. Caller holds stateMu. func (r *Reporter) appendLogRow(row *runnerv1.LogRow) { - if row == nil { - return - } row.Content = r.mask(row.Content) if step := r.currentReportedStep; step != nil { if step.LogLength == 0 { @@ -461,7 +450,7 @@ func (r *Reporter) Handle(_ context.Context, entry logging.Record) error { } } if r.shouldAppendLogRow(entry) { - r.appendLogRow(r.parseLogRow(entry)) + r.appendLogRow(logRow(entry)) } r.unlockAndNotify(urgentState) return nil @@ -475,7 +464,7 @@ func (r *Reporter) Handle(_ context.Context, entry logging.Record) error { } if step == nil { if r.shouldAppendLogRow(entry) { - r.appendLogRow(r.parseLogRow(entry)) + r.appendLogRow(logRow(entry)) } r.unlockAndNotify(false) return nil @@ -484,9 +473,6 @@ func (r *Reporter) Handle(_ context.Context, entry logging.Record) error { if step.StartedAt == nil { step.StartedAt = timestamppb.New(timestamp) urgentState = true - // The runner's own handler is per step, so an unresumed ::stop-commands:: must not - // leave the reporter suppressed, and no longer registering masks, for the whole job. - r.stopCommandEndToken = "" } // Force reporting log errors as raw output to prevent silent failures @@ -497,16 +483,14 @@ func (r *Reporter) Handle(_ context.Context, entry logging.Record) error { if ok { if rawOutput, ok := v.(bool); ok && rawOutput { - if row := r.parseLogRow(entry); row != nil { - if step.LogLength == 0 { - step.LogIndex = int64(r.logOffset + len(r.logRows)) - } - step.LogLength++ - r.appendLogRow(row) + if step.LogLength == 0 { + step.LogIndex = int64(r.logOffset + len(r.logRows)) } + step.LogLength++ + r.appendLogRow(logRow(entry)) } } else if r.shouldAppendLogRow(entry) { - r.appendLogRow(r.parseLogRow(entry)) + r.appendLogRow(logRow(entry)) } if v, ok := entry.Attr("stepResult"); ok && isJobStepEntry(entry) { if stepResult, ok := r.parseResult(v); ok { @@ -654,8 +638,8 @@ func (r *Reporter) Logf(format string, a ...any) { func (r *Reporter) logf(format string, a ...any) { if !r.duringSteps() { - // Masked like any other row: these bypass parseLogRow, but a caller can still - // interpolate a secret, such as a configured URL carrying credentials. + // Masked like any other row, as a caller can interpolate a secret such as a configured URL + // carrying credentials. r.appendLogRow(&runnerv1.LogRow{Time: timestamppb.Now(), Content: fmt.Sprintf(format, a...)}) } } @@ -1000,129 +984,8 @@ func (r *Reporter) parseResult(result any) (runnerv1.Result, bool) { return ret, ok } -// A property value never contains a raw ':' (GitHub escapes it as %3A), so excluding ':' ends -// the property list at the first '::' as GitHub does; greedily would swallow a '::' message. -var cmdRegex = regexp.MustCompile(`^::([^ :]+)( [^:]*)?::(.*)$`) - -// handleCommand takes value still escaped, so that the web UI decodes it exactly once. Only -// the branches that consume the payload here decode it. -func (r *Reporter) handleCommand(originalContent, command, properties, value string) *string { - command = strings.ToLower(command) // GitHub matches command names case-insensitively - if r.stopCommandEndToken != "" { - if !strings.EqualFold(command, r.stopCommandEndToken) { - return &originalContent - } - // Resumed here rather than from the switch, because the end token is arbitrary and a - // token naming a real command would otherwise never resume. - r.stopCommandEndToken = "" - return nil - } - - switch command { - case "add-mask": - r.addMask(runner.UnescapeCommandData(value)) - return nil - case "debug": - if r.debugOutputEnabled { - return &originalContent // kept as ::debug::, so the web UI labels and decodes it - } - return nil - - case "notice", "warning", "error": - // Gitea has no annotation store, so the annotation is rendered into the log with - // its source location instead of being dropped: that location is the whole point - // of the command for compiler and linter output. - annotation := formatAnnotation(command, properties, value) - return &annotation - case "group", "endgroup": - // Passed through: the web UI folds the log on these and decodes the payload itself. - return &originalContent - case "stop-commands": - r.stopCommandEndToken = runner.UnescapeCommandData(value) - return nil - } - return &originalContent -} - -// formatAnnotation folds the file, line, column and title the command carries into its message, -// which the web UI otherwise drops along with the rest of the properties: -// -// ::error file=main.go,line=12,col=5,title=vet::undefined: x -// ::error::main.go:12:5: vet: undefined: x -// -// The ::-form prefix is deliberate, and value is not escaped here because it arrived escaped -// and must stay that way. -func formatAnnotation(level, properties, value string) string { - props := parseCommandProperties(properties) - - prefix := props["file"] - if prefix != "" { - if props["line"] != "" { - prefix += ":" + props["line"] - if props["col"] != "" { - prefix += ":" + props["col"] - } - } - prefix += ": " - } - if props["title"] != "" { - prefix += props["title"] + ": " - } - return "::" + level + "::" + prefix + value -} - -// parseCommandProperties parses the `file=main.go,line=12` part of a workflow command. -func parseCommandProperties(properties string) map[string]string { - properties = strings.TrimSpace(properties) - if properties == "" { - return nil - } - - props := map[string]string{} - for pair := range strings.SplitSeq(properties, ",") { - key, value, ok := strings.Cut(pair, "=") - if !ok { - continue - } - // Only the property-list separators are decoded, the web UI decodes the rest. - value = strings.ReplaceAll(strings.ReplaceAll(value, "%3A", ":"), "%2C", ",") - // GitHub keys its property dictionary case-insensitively, so `File=` works there too. - props[strings.ToLower(strings.TrimSpace(key))] = value - } - // GitHub's toolkit emits `col`; accept `column` as well, which some tools write instead. - if props["col"] == "" { - props["col"] = props["column"] - } - return props -} - -func cutPrefixFold(s, prefix string) (string, bool) { - if len(s) < len(prefix) || !strings.EqualFold(s[:len(prefix)], prefix) { - return s, false - } - return s[len(prefix):], true -} - -func (r *Reporter) parseLogRow(entry logging.Record) *runnerv1.LogRow { - content := strings.TrimRight(entry.Message, "\r\n") - - // cmdRegex only covers the ::cmd:: form, so the ##[add-mask] one would otherwise reach - // the log carrying its own secret. Registered and dropped like its ::add-mask:: twin. - if arg, ok := cutPrefixFold(content, "##[add-mask]"); ok { - r.addMask(runner.UnescapeLegacyCommand(arg)) - return nil - } - - matches := cmdRegex.FindStringSubmatch(content) - if matches != nil { - if output := r.handleCommand(content, matches[1], matches[2], matches[3]); output != nil { - content = *output - } else { - return nil - } - } - - return &runnerv1.LogRow{Time: timestamppb.New(entry.Time), Content: content} +func logRow(entry logging.Record) *runnerv1.LogRow { + return &runnerv1.LogRow{Time: timestamppb.New(entry.Time), Content: strings.TrimRight(entry.Message, "\r\n")} } // mask repairs the content first, so a secret the repair itself spells out is still caught. @@ -1130,10 +993,12 @@ func (r *Reporter) mask(content string) string { return r.logReplacer.Replace(strings.ToValidUTF8(content, "?")) } -// addMask deliberately leaves the process-wide masker alone. Its entries come from every live +// AddMask deliberately leaves the process-wide masker alone. Its entries come from every live // task at once, so a workflow could otherwise mask "error" there and rewrite the runner's own // log, and every other task's, for the rest of the job. -func (r *Reporter) addMask(msg string) { +func (r *Reporter) AddMask(msg string) { + r.stateMu.Lock() + defer r.stateMu.Unlock() r.oldnew = runner.AppendSecretMasker(r.oldnew, msg) r.logReplacer = runner.NewSecretReplacer(r.oldnew) } diff --git a/internal/pkg/report/reporter_test.go b/internal/pkg/report/reporter_test.go index eb3c631f..4d71e8f9 100644 --- a/internal/pkg/report/reporter_test.go +++ b/internal/pkg/report/reporter_test.go @@ -35,259 +35,19 @@ import ( "google.golang.org/protobuf/types/known/timestamppb" ) -func TestReporter_parseLogRow(t *testing.T) { - tests := []struct { - name string - debugOutputEnabled bool - args []string - want []string - }{ - { - "No command", false, - []string{"Hello, world!"}, - []string{"Hello, world!"}, - }, - { - "Add-mask", false, - []string{ - "foo mysecret bar", - "::add-mask::mysecret", - "foo mysecret bar", - }, - []string{ - "foo mysecret bar", - "", - "foo *** bar", - }, - }, - { - "Add-mask-multiline", false, - []string{ - "foo mysecret bar", - "::add-mask::LINE1%0ALINE2", - "foo LINE1 bar", - }, - []string{ - "foo mysecret bar", - "", - "foo *** bar", - }, - }, - { - "Debug enabled", true, - []string{ - "::debug::GitHub Actions runtime token access controls", - // Left escaped: the web UI decodes it, and a real newline would not survive storage. - "::debug::first%0Asecond", - }, - []string{ - "::debug::GitHub Actions runtime token access controls", - "::debug::first%0Asecond", - }, - }, - { - "Debug not enabled", false, - []string{ - "::debug::GitHub Actions runtime token access controls", - }, - []string{ - "", - }, - }, - // The three annotation levels share one code path, so the property shapes are only - // exercised under "error"; notice and warning just prove the level token round-trips. - { - "notice", false, - []string{ - "::notice::Gosh, that's not going to work", - }, - []string{ - "::notice::Gosh, that's not going to work", - }, - }, - { - "warning", false, - []string{ - "::warning::Gosh, that's not going to work", - }, - []string{ - "::warning::Gosh, that's not going to work", - }, - }, - { - "error", false, - []string{ - "::error file=file.name,line=42,endLine=48,title=Cool Title::Gosh, that's not going to work", - "::error::Gosh, that's not going to work", - "::error file=file.name,line=42,col=7::Gosh, that's not going to work", - // The message keeps its own '::', the property list ends at the first one. - "::error file=main.cpp,line=12::no member named 'foo' in 'std::vector'", - // GitHub matches property names case-insensitively. - "::error File=file.name,Line=42,Col=7::Gosh, that's not going to work", - // Only the property separators are decoded here, %25/%0A are left for the web UI. - "::error file=a%3Ab.go,title=100%252C::still %25 escaped%0Aand multi-line", - }, - []string{ - "::error::file.name:42: Cool Title: Gosh, that's not going to work", - "::error::Gosh, that's not going to work", - "::error::file.name:42:7: Gosh, that's not going to work", - "::error::main.cpp:12: no member named 'foo' in 'std::vector'", - "::error::file.name:42:7: Gosh, that's not going to work", - "::error::a:b.go: 100%252C: still %25 escaped%0Aand multi-line", - }, - }, - { - "group", false, - []string{ - "::group::", - "::endgroup::", - }, - []string{ - "::group::", - "::endgroup::", - }, - }, - { - "stop-commands", false, - []string{ - "::add-mask::foo", - "::stop-commands::myverycoolstoptoken", - "::add-mask::bar", - "::debug::Stuff", - "myverycoolstoptoken", - "::add-mask::baz", - "::myverycoolstoptoken::", - "::add-mask::wibble", - "foo bar baz wibble", - }, - []string{ - "", - "", - "::add-mask::bar", - "::debug::Stuff", - "myverycoolstoptoken", - "::add-mask::baz", - "", - "", - "*** bar baz ***", - }, - }, - { - // a token naming a real command must still resume - "stop-commands with a command-named token", false, - []string{ - "::stop-commands::add-mask", - "::set-output name=x::suppressed", - "::add-mask::", - "::add-mask::masked", - "masked", - }, - []string{ - "", - "::set-output name=x::suppressed", - "", - "", - "***", - }, - }, - { - "unknown command", false, - []string{ - "::set-mask::foo", - }, - []string{ - "::set-mask::foo", - }, - }, - } - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - r := &Reporter{ - logReplacer: strings.NewReplacer(), - debugOutputEnabled: tt.debugOutputEnabled, - } - for idx, arg := range tt.args { - rv := r.parseLogRow(logging.Record{Message: arg}) - got := "" +func TestReporter_CompositeStepResultDoesNotFinishStep(t *testing.T) { + reporter := &Reporter{state: &runnerv1.TaskState{}, logReplacer: strings.NewReplacer()} + reporter.ResetSteps(newTestSteps(1)) + data := map[string]any{"stage": runner.StageMain, "stepNumber": 0, "stepID": []string{"0", "0"}, "raw_output": true, "stepResult": model.StepStatusFailure} - if rv != nil { - got = r.mask(rv.Content) - } + require.NoError(t, fire(reporter, logEntry{Data: data})) + assert.Equal(t, runnerv1.Result_RESULT_UNSPECIFIED, reporter.state.Steps[0].Result) - assert.Equal(t, tt.want[idx], got) - } - }) - } -} - -// Both add-mask forms must register the secret and drop their own row: the runner forwards -// the raw line, so failing to consume it writes the secret straight to the job log. -func TestReporter_parseLogRowAddMask(t *testing.T) { - for _, line := range []string{"::add-mask::supersecret", "##[add-mask]supersecret"} { - r := &Reporter{logReplacer: strings.NewReplacer()} - - assert.Nil(t, r.parseLogRow(logging.Record{Message: line}), line) - - assert.Equal(t, "using *** now", r.mask("using supersecret now"), line) - } -} - -func TestReporter_Handle(t *testing.T) { - t.Run("ignore command lines", func(t *testing.T) { - client := mocks.NewClient(t) - client.On("UpdateLog", mock.Anything, mock.Anything).Return(func(_ context.Context, req *connect_go.Request[runnerv1.UpdateLogRequest]) (*connect_go.Response[runnerv1.UpdateLogResponse], error) { - t.Logf("Received UpdateLog: %s", req.Msg.String()) - return connect_go.NewResponse(&runnerv1.UpdateLogResponse{ - AckIndex: req.Msg.Index + int64(len(req.Msg.Rows)), - }), nil - }) - client.On("UpdateTask", mock.Anything, mock.Anything).Return(func(_ context.Context, req *connect_go.Request[runnerv1.UpdateTaskRequest]) (*connect_go.Response[runnerv1.UpdateTaskResponse], error) { - t.Logf("Received UpdateTask: %s", req.Msg.String()) - return connect_go.NewResponse(&runnerv1.UpdateTaskResponse{}), nil - }) - ctx, cancel := context.WithCancel(t.Context()) - taskCtx, err := structpb.NewStruct(map[string]any{}) - require.NoError(t, err) - cfg, _ := config.LoadDefault("") - reporter := NewReporter(ctx, cancel, client, &runnerv1.Task{ - Context: taskCtx, - }, cfg) - reporter.RunDaemon() - defer func() { - require.NoError(t, reporter.Close("")) - }() - reporter.ResetSteps(newTestSteps(5)) - - dataStep0 := map[string]any{ - "stage": "Main", - "stepNumber": 0, - "raw_output": true, - } - - require.NoError(t, fire(reporter, logEntry{Message: "regular log line", Data: dataStep0})) - require.NoError(t, fire(reporter, logEntry{Message: "::debug::debug log line", Data: dataStep0})) - require.NoError(t, fire(reporter, logEntry{Message: "regular log line", Data: dataStep0})) - require.NoError(t, fire(reporter, logEntry{Message: "::debug::debug log line", Data: dataStep0})) - require.NoError(t, fire(reporter, logEntry{Message: "::debug::debug log line", Data: dataStep0})) - require.NoError(t, fire(reporter, logEntry{Message: "regular log line", Data: dataStep0})) - require.NoError(t, fire(reporter, logEntry{Message: "composite step result", Data: map[string]any{ - "stage": "Main", - "stepID": []string{"0", "0"}, - "stepNumber": 0, - "raw_output": true, - "stepResult": model.StepStatusFailure, - }})) - assert.Equal(t, runnerv1.Result_RESULT_UNSPECIFIED, reporter.state.Steps[0].Result) - require.NoError(t, fire(reporter, logEntry{Message: "step result", Data: map[string]any{ - "stage": "Main", - "stepNumber": 0, - "raw_output": true, - "stepResult": model.StepStatusSuccess, - }})) - assert.Equal(t, runnerv1.Result_RESULT_SUCCESS, reporter.state.Steps[0].Result) - - assert.Equal(t, int64(5), reporter.state.Steps[0].LogLength) - }) + delete(data, "stepID") + data["stepResult"] = model.StepStatusSuccess + require.NoError(t, fire(reporter, logEntry{Data: data})) + assert.Equal(t, runnerv1.Result_RESULT_SUCCESS, reporter.state.Steps[0].Result) + assert.Equal(t, int64(2), reporter.state.Steps[0].LogLength) } func TestReporter_LogLevelFiltering(t *testing.T) { @@ -1047,7 +807,6 @@ func TestReporter_StopHeartbeats(t *testing.T) { func TestAppendLogRow(t *testing.T) { r := &Reporter{logReplacer: strings.NewReplacer("supersecret", "***")} - r.appendLogRow(nil) r.appendLogRow(&runnerv1.LogRow{Time: timestamppb.Now(), Content: "hello supersecret"}) require.Len(t, r.logRows, 1) assert.Equal(t, "hello ***", r.logRows[0].Content) @@ -1056,6 +815,8 @@ func TestAppendLogRow(t *testing.T) { r = &Reporter{logReplacer: strings.NewReplacer("a?b", "***")} r.appendLogRow(&runnerv1.LogRow{Time: timestamppb.Now(), Content: "a\xffb"}) assert.Equal(t, "***", r.logRows[0].Content) + + assert.Equal(t, "::debug::d%0Anext", logRow(logging.Record{Message: "::debug::d%0Anext\r\n"}).Content) } func TestReporter_Enabled(t *testing.T) { @@ -1122,7 +883,6 @@ func TestReporter_DebugSettingsAreNotMasked(t *testing.T) { }, &config.Config{}) defer deregisterGlobalMasks(reporter) - assert.True(t, reporter.debugOutputEnabled) assert.Equal(t, "debug is true", reporter.mask("debug is true")) assert.Equal(t, "***", reporter.mask("s3cr3t"))