diff --git a/AGENTS.md b/AGENTS.md index f3b7a99a..912d8884 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -8,6 +8,7 @@ - Never force-push, amend, or squash unless asked. Use new commits and normal push for pull request updates - Comments: write almost none, short and preferably same-line, explaining why for a future reader. Never narrate code, the change or the prompt. Preserve existing ones that still apply - Add the current year into the copyright header of new `.go` files +- Read `DEVELOPMENT.md` for internals and conventions - Ensure no trailing whitespace in edited files - Run `make fmt` after `.go` edits, `make tidy` after `go.mod` edits, and `make checks` for the non-lint source checks - Lint what changed with `make lint-go`, and `make lint-go-windows` for Windows and platform-split files diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md new file mode 100644 index 00000000..0413bd58 --- /dev/null +++ b/DEVELOPMENT.md @@ -0,0 +1,32 @@ +# Development + +## Job log line format + +Gitea stores one log row per line and its web UI decodes the payload, so getting the encoding +wrong never fails a test here, it only shows up in the browser. + +**A row cannot contain a real newline.** `FormatLog` rewrites `\n` to a literal backslash-n and +truncates at 64 KiB on a byte boundary. + +**The payload of a line starting with a recognised prefix is decoded**, with the escape set +depending on the prefix: + +| prefix | decodes | +| --- | --- | +| `##[error]` `##[warning]` `##[notice]` `##[debug]` `##[group]` `##[endgroup]` `##[add-matcher]` | `%25` `%0D` `%0A` `%3B` `%5D` | +| `::error::` `::warning::` `::notice::` `::debug::` (with or without ` key=value` properties), `::group::` `::endgroup::` `::add-matcher::` | `%25` `%0D` `%0A` | +| `##[command]` `[command]`, or no recognised prefix | nothing | + +### Rules + +- **Emitting a command line?** Escape the payload with `runner.EscapeCommandData`. One escaper + 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 + decoded once. Decoding here double-decodes and destroys multi-line. +- **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. diff --git a/act/runner/action_composite.go b/act/runner/action_composite.go index 6dd12acd..bdbc4eeb 100644 --- a/act/runner/action_composite.go +++ b/act/runner/action_composite.go @@ -186,10 +186,10 @@ func (rc *RunContext) compositeExecutor(action *model.Action) *compositeSteps { err := rc.newCompositeCommandExecutor(step.main())(ctx) if err != nil { - logger.Errorf("%v", err) + logger.Errorf("##[error]%s", EscapeCommandData(err.Error())) common.SetJobError(ctx, err) } else if ctx.Err() != nil { - logger.Errorf("%v", ctx.Err()) + logger.Errorf("##[error]%s", EscapeCommandData(ctx.Err().Error())) common.SetJobError(ctx, ctx.Err()) } return nil @@ -248,10 +248,10 @@ func newCompositeStepLogExecutor(runStep common.Executor, stepID string) common. logger := common.Logger(ctx) err := runStep(ctx) if err != nil { - logger.Errorf("%v", err) + logger.Errorf("##[error]%s", EscapeCommandData(err.Error())) common.SetJobError(ctx, err) } else if ctx.Err() != nil { - logger.Errorf("%v", ctx.Err()) + logger.Errorf("##[error]%s", EscapeCommandData(ctx.Err().Error())) common.SetJobError(ctx, ctx.Err()) } return nil diff --git a/act/runner/command.go b/act/runner/command.go index 1ee75778..ef8fc836 100644 --- a/act/runner/command.go +++ b/act/runner/command.go @@ -6,6 +6,7 @@ package runner import ( "context" + "fmt" "regexp" "strings" @@ -45,17 +46,24 @@ func (rc *RunContext) commandHandler(ctx context.Context) common.LineHandler { return true } - if resumeCommand != "" && command != resumeCommand { + if resumeCommand != "" { // There should not be any emojis in the log output for Gitea. - // The code in the switch statement is the same. // 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 command == resumeCommand { + resumeCommand = "" + } return true } arg = UnescapeCommandData(arg) kvPairs = unescapeKvPairs(kvPairs) + if (command == "set-env" || command == "add-path") && rc.refuseUnsecureCommand(ctx, command) { + return true + } switch command { case "set-env": rc.setEnv(ctx, kvPairs, arg) @@ -63,27 +71,20 @@ func (rc *RunContext) commandHandler(ctx context.Context) common.LineHandler { rc.setOutput(ctx, kvPairs, arg) case "add-path": rc.addPath(ctx, arg) - case "debug": - logger.Infof("%s", line) - case "warning": - logger.Infof("%s", line) - case "error": - logger.Infof("%s", line) 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. case "stop-commands": resumeCommand = arg logger.Infof("%s", line) - case resumeCommand: - resumeCommand = "" - logger.Infof("%s", line) case "save-state": logger.Infof("%s", line) rc.saveState(ctx, kvPairs, arg) - case "add-matcher": - logger.Infof("%s", line) 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) } @@ -92,6 +93,52 @@ func (rc *RunContext) commandHandler(ctx context.Context) common.LineHandler { } } +const allowUnsecureCommandsVar = "ACTIONS_ALLOW_UNSECURE_COMMANDS" + +// refuseUnsecureCommand reports whether a deprecated ::set-env:: or ::add-path:: command must +// not run, recording the error that fails the step. GitHub disabled both because a step that +// echoes untrusted content can use them to set NODE_OPTIONS or PATH for every later step. +func (rc *RunContext) refuseUnsecureCommand(ctx context.Context, command string) bool { + if rc.allowUnsecureCommandsOptIn() { + return false + } + + // The step executor logs the failure itself, so keep this line's wording distinct. + common.Logger(ctx).WithField(rawOutputField, true).Errorf("##[error]%s", EscapeCommandData(fmt.Sprintf( + "The `%s` command is disabled: it can set the environment of every later step from untrusted output. "+ + "Write to $GITHUB_ENV or $GITHUB_PATH instead, or set ACTIONS_ALLOW_UNSECURE_COMMANDS to allow it", + command))) + + rc.unsecureCommandMu.Lock() + defer rc.unsecureCommandMu.Unlock() + if rc.unsecureCommandErr == nil { + rc.unsecureCommandErr = fmt.Errorf("the `%s` workflow command is disabled", command) + } + return true +} + +// allowUnsecureCommandsOptIn reports whether the workflow itself asked for the deprecated +// commands, from any env scope, as it can on GitHub. +func (rc *RunContext) allowUnsecureCommandsOptIn() bool { + return isTruthyEnv(rc.currentStepEnv()[allowUnsecureCommandsVar]) || + isTruthyEnv(rc.Env[allowUnsecureCommandsVar]) || + isTruthyEnv(rc.GlobalEnv[allowUnsecureCommandsVar]) +} + +// isTruthyEnv mirrors GitHub's bool.TryParse: only "true", in any casing. +func isTruthyEnv(v string) bool { + return strings.EqualFold(strings.TrimSpace(v), "true") +} + +// takeUnsecureCommandError returns and clears the error left by a refused command. +func (rc *RunContext) takeUnsecureCommandError() error { + rc.unsecureCommandMu.Lock() + defer rc.unsecureCommandMu.Unlock() + err := rc.unsecureCommandErr + rc.unsecureCommandErr = nil + return err +} + func (rc *RunContext) setEnv(ctx context.Context, kvPairs map[string]string, arg string) { name := kvPairs["name"] common.Logger(ctx).Infof("::set-env:: %s=%s", name, arg) @@ -161,9 +208,9 @@ var ( 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, +// 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 { +func EscapeCommandData(arg string) string { return commandDataEscaper.Replace(arg) } diff --git a/act/runner/command_test.go b/act/runner/command_test.go index 5869456c..16cdb5a4 100644 --- a/act/runner/command_test.go +++ b/act/runner/command_test.go @@ -16,12 +16,18 @@ import ( "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) +// unsecureRC opts into ::set-env:: and ::add-path::, which are refused without it. +func unsecureRC() *RunContext { + return &RunContext{Env: map[string]string{allowUnsecureCommandsVar: "true"}} +} + func TestSetEnv(t *testing.T) { a := assert.New(t) ctx := context.Background() - rc := new(RunContext) + rc := unsecureRC() handler := rc.commandHandler(ctx) handler("::set-env name=x::valz\n") @@ -31,7 +37,7 @@ func TestSetEnv(t *testing.T) { func TestStopCommandsKeepsSuppressedLinesInLog(t *testing.T) { a := assert.New(t) ctx := context.Background() - rc := new(RunContext) + rc := unsecureRC() handler := rc.commandHandler(ctx) // Stop command processing until the matching end token is seen. @@ -84,7 +90,7 @@ func TestSetOutput(t *testing.T) { func TestAddpath(t *testing.T) { a := assert.New(t) ctx := context.Background() - rc := new(RunContext) + rc := unsecureRC() handler := rc.commandHandler(ctx) handler("::add-path::/zoo\n") @@ -99,7 +105,7 @@ func TestStopCommands(t *testing.T) { a := assert.New(t) ctx := common.WithLogger(context.Background(), logger) - rc := new(RunContext) + rc := unsecureRC() handler := rc.commandHandler(ctx) handler("::set-env name=x::valz\n") @@ -119,10 +125,26 @@ func TestStopCommands(t *testing.T) { 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(context.Background()) + + 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 := context.Background() - rc := new(RunContext) + rc := unsecureRC() handler := rc.commandHandler(ctx) handler("##[add-path]/zoo\n") @@ -218,6 +240,44 @@ func TestSaveState(t *testing.T) { 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%25b%0Dc%0Ad%250A", EscapeCommandData("a%b\rc\nd%0A")) a.Equal("a%b\rc\nd%0A", UnescapeCommandData("a%25b%0Dc%0Ad%250A")) } + +func TestUnsecureCommands(t *testing.T) { + tests := []struct { + name string + jobEnv map[string]string + stepEnv map[string]string + optedIn bool + }{ + {name: "refused with no opt-in"}, + // GitHub reads the opt-in with bool.TryParse, so "1" is not one. + {name: "refused for a value bool.TryParse rejects", jobEnv: map[string]string{allowUnsecureCommandsVar: "1"}}, + {name: "opted in through the step environment", stepEnv: map[string]string{allowUnsecureCommandsVar: "true"}, optedIn: true}, + {name: "opted in through the job environment", jobEnv: map[string]string{allowUnsecureCommandsVar: "TRUE"}, optedIn: true}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + a := assert.New(t) + rc := &RunContext{Env: tt.jobEnv} + rc.setCurrentStepEnv(tt.stepEnv) + handler := rc.commandHandler(context.Background()) + + handler("::set-env name=x::valz\n") + handler("::add-path::/opt/bin\n") + + if !tt.optedIn { + a.Empty(rc.Env["x"]) + a.Empty(rc.ExtraPath) + // The refusal fails the step that produced it, once. + require.ErrorContains(t, rc.takeUnsecureCommandError(), "set-env") + a.NoError(rc.takeUnsecureCommandError()) + return + } + a.Equal("valz", rc.Env["x"]) + a.Equal([]string{"/opt/bin"}, rc.ExtraPath) + a.NoError(rc.takeUnsecureCommandError()) + }) + } +} diff --git a/act/runner/job_executor.go b/act/runner/job_executor.go index 753a1a60..2559ac83 100644 --- a/act/runner/job_executor.go +++ b/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]%s", escapeCommandData(err.Error())) + common.Logger(ctx).Errorf("##[error]%s", EscapeCommandData(err.Error())) common.SetJobError(ctx, err) rc.markFailed() } @@ -260,7 +260,7 @@ func newJobExecutor(info jobInfo, sf stepFactory, rc *RunContext) common.Executo logger.Infof("Cleaning up container for job %s", rc.JobName) if err = info.stopContainer()(ctx); err != nil { - logger.Errorf("Error while stop job container: %v", err) + logger.Errorf("##[error]%s", EscapeCommandData("Error while stop job container: "+err.Error())) } // For Gitea diff --git a/act/runner/job_hooks.go b/act/runner/job_hooks.go index 1ca4a8ce..e39ee739 100644 --- a/act/runner/job_hooks.go +++ b/act/runner/job_hooks.go @@ -45,7 +45,7 @@ func (rc *RunContext) runJobHook(ctx context.Context, hookPath, name string) err cmd, shell := hookCommand(hookPath) rawLogger := common.Logger(ctx).WithField(rawOutputField, true) defer rawLogger.Infof("::endgroup::") - rawLogger.Infof("::group::Run '%s'", escapeCommandData(hookPath)) + rawLogger.Infof("::group::Run '%s'", EscapeCommandData(hookPath)) rawLogger.Infof("A %s hook has been configured by the runner administrator", name) if shell != "" { rawLogger.Infof("shell: %s", shell) diff --git a/act/runner/logger.go b/act/runner/logger.go index 5f5c4288..615fc0e4 100644 --- a/act/runner/logger.go +++ b/act/runner/logger.go @@ -250,7 +250,7 @@ func AppendSecretMasker(oldnew []string, v string) []string { 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), "***") + ret = append(ret, EscapeCommandData(tm), "***") } } } diff --git a/act/runner/run_context.go b/act/runner/run_context.go index 29e53edf..1bda7c7f 100644 --- a/act/runner/run_context.go +++ b/act/runner/run_context.go @@ -22,6 +22,7 @@ import ( "runtime" "slices" "strings" + "sync" "time" "gitea.com/gitea/runner/act/common" @@ -83,6 +84,25 @@ type RunContext struct { // failures. Those failures must still make success() false and failure() true for later // main-step if evaluation. jobFailed bool + // stepEnv is a copy of the running step's environment, so that workflow commands parsed out + // of the container's output can be judged against it. Written by runStepExecutor and read on + // the log-writer goroutine, hence unsecureCommandMu, which also guards unsecureCommandErr. + stepEnv map[string]string + unsecureCommandErr error // refused ::set-env::/::add-path::, turned into a step failure + unsecureCommandMu sync.Mutex +} + +// setCurrentStepEnv records the environment of the step about to run. +func (rc *RunContext) setCurrentStepEnv(env map[string]string) { + rc.unsecureCommandMu.Lock() + defer rc.unsecureCommandMu.Unlock() + rc.stepEnv = env +} + +func (rc *RunContext) currentStepEnv() map[string]string { + rc.unsecureCommandMu.Lock() + defer rc.unsecureCommandMu.Unlock() + return rc.stepEnv } // markCancelled flags the job as cancelled so subsequent step `if` evaluations and the diff --git a/act/runner/step.go b/act/runner/step.go index 01095862..71049684 100644 --- a/act/runner/step.go +++ b/act/runner/step.go @@ -165,9 +165,22 @@ func runStepExecutor(step step, stage stepStage, executor common.Executor) commo } _ = rc.JobContainer.Copy(actPath, files...)(ctx) + // The command handler needs the step's env to judge ACTIONS_ALLOW_UNSECURE_COMMANDS. + // Cloned: the step executor keeps writing to its own env map after this point, on a + // different goroutine from the command handler that reads it. + rc.setCurrentStepEnv(maps0.Clone(*step.getEnv())) + defer rc.setCurrentStepEnv(nil) + _ = rc.takeUnsecureCommandError() // a refusal from before any step belongs to no step + timeoutctx, cancelTimeOut := evaluateStepTimeout(ctx, rc.ExprEval, stepModel) defer cancelTimeOut() err = executor(timeoutctx) + // Always take it, so the job-scoped error cannot leak onto a later step. A refusal + // fails the step as it does on GitHub, but the executor's own error wins. + insecureErr := rc.takeUnsecureCommandError() + if err == nil { + err = insecureErr + } if err == nil { logger.WithField("stepResult", stepResult.Outcome).Infof("Success - %s %s", stage, stepString) @@ -181,7 +194,7 @@ func runStepExecutor(step step, stage stepStage, executor common.Executor) commo } if continueOnError { - logger.Errorf("##[error]%s", escapeCommandData(err.Error())) + logger.Errorf("##[error]%s", EscapeCommandData(err.Error())) logger.Infof("Failed but continue next step") err = nil stepResult.Conclusion = model.StepStatusSuccess diff --git a/act/runner/step_run.go b/act/runner/step_run.go index 3a04b7ed..cae2a639 100644 --- a/act/runner/step_run.go +++ b/act/runner/step_run.go @@ -18,6 +18,7 @@ import ( "gitea.com/gitea/runner/act/model" "github.com/kballard/go-shellquote" + "github.com/sirupsen/logrus" yaml "go.yaml.in/yaml/v4" ) @@ -63,7 +64,7 @@ func (sr *stepRun) printRunScriptActionDetails(ctx context.Context) { normalized := strings.TrimRight(strings.ReplaceAll(sr.interpolatedScript, "\r\n", "\n"), "\n") - rawLogger.Infof("::group::Run %s", escapeCommandData(sr.runScriptGroupTitle(normalized))) + rawLogger.Infof("::group::Run %s", EscapeCommandData(sr.runScriptGroupTitle(normalized))) if normalized != "" { for line := range strings.SplitSeq(normalized, "\n") { @@ -90,12 +91,12 @@ func printRunActionHeader(ctx context.Context, step *model.Step, env map[string] if step.Name != "" { title = step.Name } - rawLogger.Infof("::group::Run %s", escapeCommandData(title)) + rawLogger.Infof("::group::Run %s", EscapeCommandData(title)) if len(step.With) > 0 { rawLogger.Infof("with:") for _, k := range slices.Sorted(maps.Keys(step.With)) { - rawLogger.Infof(" %s: %s", k, step.With[k]) + logKeyedValue(rawLogger, k, step.With[k]) } } @@ -129,7 +130,17 @@ func printStepEnvBlock(ctx context.Context, step *model.Step, env map[string]str if caseInsensitive { lookupKey = strings.ToUpper(k) } - rawLogger.Infof(" %s: %s", k, envLookup[lookupKey]) + logKeyedValue(rawLogger, k, envLookup[lookupKey]) + } +} + +// logKeyedValue prints one row per line of value: Gitea stores one log row per line, so an +// embedded newline would reach the user as a literal "\n". +func logKeyedValue(rawLogger *logrus.Entry, key, value string) { + lines := strings.Split(strings.ReplaceAll(value, "\r\n", "\n"), "\n") + rawLogger.Infof(" %s: %s", key, lines[0]) + for _, line := range lines[1:] { + rawLogger.Infof(" %s", line) } } diff --git a/act/runner/step_test.go b/act/runner/step_test.go index fa9d95c5..50221e78 100644 --- a/act/runner/step_test.go +++ b/act/runner/step_test.go @@ -6,6 +6,7 @@ package runner import ( "context" + "errors" "testing" "gitea.com/gitea/runner/act/common" @@ -14,6 +15,7 @@ import ( log "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" + "github.com/stretchr/testify/require" yaml "go.yaml.in/yaml/v4" ) @@ -354,3 +356,48 @@ func TestIsContinueOnError(t *testing.T) { assertObject.False(continueOnError) assertObject.Error(err) } + +// A refused ::set-env::/::add-path:: records a job-scoped error. When the step that +// produced it also fails on its own, the refusal must be cleared at the step boundary, so +// it fails only that step and never leaks onto a later step that runs anyway (if: always()). +func TestRunStepExecutorDoesNotLeakRefusalToNextStep(t *testing.T) { + cm := &containerMock{} + noop := func(context.Context) error { return nil } + cm.On("Copy", mock.Anything, mock.Anything).Return(noop) + cm.On("UpdateFromEnv", mock.Anything, mock.Anything).Return(noop) + + rc := &RunContext{ + Config: &Config{Env: map[string]string{}}, + Run: &model.Run{ + JobID: "1", + Workflow: &model.Workflow{Jobs: map[string]*model.Job{"1": {}}}, + }, + Env: map[string]string{}, + StepResults: map[string]*model.StepResult{}, + JobContainer: cm, + } + rc.ExprEval = rc.NewExpressionEvaluator(context.Background()) + // Dryrun skips reading the path file back from the (mocked) container. + ctx := common.WithDryrun(context.Background(), true) + + // A refusal parsed out of the job container's own output belongs to no step, so the + // first step must not be failed by it. + rc.commandHandler(ctx)("::set-env name=setup::y\n") + stepSetup := &stepRun{RunContext: rc, Step: &model.Step{ID: "setup"}, env: map[string]string{}} + require.NoError(t, runStepExecutor(stepSetup, stepStageMain, func(context.Context) error { return nil })(ctx)) + + // Step A refuses a ::set-env:: and then fails on its own. + stepA := &stepRun{RunContext: rc, Step: &model.Step{ID: "a"}, env: map[string]string{}} + errA := runStepExecutor(stepA, stepStageMain, func(context.Context) error { + rc.commandHandler(ctx)("::set-env name=x::y\n") + return errors.New("boom") + })(ctx) + // The step fails with its own error, not the refusal. + require.ErrorContains(t, errA, "boom") + + // Step B runs despite step A's failure (if: always()) and issues no unsecure command; + // it must not inherit step A's refusal. + stepB := &stepRun{RunContext: rc, Step: &model.Step{ID: "b", If: yaml.Node{Value: "always()"}}, env: map[string]string{}} + errB := runStepExecutor(stepB, stepStageMain, func(context.Context) error { return nil })(ctx) + require.NoError(t, errB) +} diff --git a/act/runner/testdata/GITHUB_ENV-use-in-env-ctx/push.yml b/act/runner/testdata/GITHUB_ENV-use-in-env-ctx/push.yml index af33415e..26919866 100644 --- a/act/runner/testdata/GITHUB_ENV-use-in-env-ctx/push.yml +++ b/act/runner/testdata/GITHUB_ENV-use-in-env-ctx/push.yml @@ -3,6 +3,7 @@ jobs: _: runs-on: ubuntu-latest env: + ACTIONS_ALLOW_UNSECURE_COMMANDS: 'true' MYGLOBALENV3: myglobalval3 steps: - uses: actions/checkout@v4 diff --git a/act/runner/testdata/commands/push.yml b/act/runner/testdata/commands/push.yml index 96c3b2ea..fe279d66 100644 --- a/act/runner/testdata/commands/push.yml +++ b/act/runner/testdata/commands/push.yml @@ -4,6 +4,8 @@ on: push jobs: build: runs-on: ubuntu-latest + env: + ACTIONS_ALLOW_UNSECURE_COMMANDS: 'true' steps: - name: TEST set-env run: echo "::set-env name=foo::bar" diff --git a/internal/app/run/runner.go b/internal/app/run/runner.go index fe36263f..0afd3cc6 100644 --- a/internal/app/run/runner.go +++ b/internal/app/run/runner.go @@ -607,7 +607,8 @@ func (r *Runner) registerExternalCacheJob(token string, cred artifactcache.JobCr }); err != nil { log.Warnf("cache external_server register failed (%s): %v", base, err) if reporter != nil { - reporter.Logf("::warning::cache external_server register failed (%s): %v — cache requests from this job will be unauthenticated and likely return 401", base, err) + reporter.Logf("::warning::%s", runner.EscapeCommandData(fmt.Sprintf( + "cache external_server register failed (%s): %v — cache requests from this job will be unauthenticated and likely return 401", base, err))) } } else { resultsURL, _ = body["results_url"].(string) // absent from a server too old to forward @@ -617,7 +618,8 @@ func (r *Runner) registerExternalCacheJob(token string, cred artifactcache.JobCr map[string]any{"token": token}); err != nil { log.Warnf("cache external_server revoke failed (%s): %v", base, err) if reporter != nil { - reporter.Logf("::warning::cache external_server revoke failed (%s): %v", base, err) + reporter.Logf("::warning::%s", runner.EscapeCommandData(fmt.Sprintf( + "cache external_server revoke failed (%s): %v", base, err))) } } }, resultsURL diff --git a/internal/pkg/report/reporter.go b/internal/pkg/report/reporter.go index 82f2bfab..951811e8 100644 --- a/internal/pkg/report/reporter.go +++ b/internal/pkg/report/reporter.go @@ -255,6 +255,9 @@ func (r *Reporter) Fire(entry *log.Entry) 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 @@ -396,10 +399,9 @@ func (r *Reporter) Logf(format string, a ...any) { func (r *Reporter) logf(format string, a ...any) { if !r.duringSteps() { - r.logRows = append(r.logRows, &runnerv1.LogRow{ - Time: timestamppb.Now(), - Content: fmt.Sprintf(format, a...), - }) + // Masked like any other row: these bypass parseLogRow, but a caller can still + // interpolate a secret, such as a configured URL carrying credentials. + r.logRows = append(r.logRows, r.newLogRow(timestamppb.Now(), fmt.Sprintf(format, a...))) } } @@ -700,66 +702,128 @@ func (r *Reporter) parseResult(result any) (runnerv1.Result, bool) { return ret, ok } -var cmdRegex = regexp.MustCompile(`^::([^ :]+)( .*)?::(.*)$`) +// 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(`^::([^ :]+)( [^:]*)?::(.*)$`) -func (r *Reporter) handleCommand(originalContent, command, value string) *string { - if r.stopCommandEndToken != "" && command != r.stopCommandEndToken { - return &originalContent +// 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 { + if r.stopCommandEndToken != "" { + if 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(value) + r.addMask(runner.UnescapeCommandData(value)) return nil case "debug": if r.debugOutputEnabled { - return &value + return &originalContent // kept as ::debug::, so the web UI labels and decodes it } return nil - case "notice": - // Not implemented yet, so just return the original content. - return &originalContent - case "warning": - // Not implemented yet, so just return the original content. - return &originalContent - case "error": - // Not implemented yet, so just return the original content. - return &originalContent - case "group": - // Returning the original content, because I think the frontend - // will use it when rendering the output. - return &originalContent - case "endgroup": - // Ditto + 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 = value - return nil - case r.stopCommandEndToken: - r.stopCommandEndToken = "" + 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 (r *Reporter) parseLogRow(entry *log.Entry) *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 := strings.CutPrefix(content, "##[add-mask]"); ok { + r.addMask(runner.UnescapeCommandData(arg)) + return nil + } + matches := cmdRegex.FindStringSubmatch(content) if matches != nil { - if output := r.handleCommand(content, matches[1], runner.UnescapeCommandData(matches[3])); output != nil { + if output := r.handleCommand(content, matches[1], matches[2], matches[3]); output != nil { content = *output } else { return nil } } - content = r.logReplacer.Replace(content) + return r.newLogRow(timestamppb.New(entry.Time), content) +} +// newLogRow applies the masking and validation every row must carry, whatever built it. +func (r *Reporter) newLogRow(t *timestamppb.Timestamp, content string) *runnerv1.LogRow { return &runnerv1.LogRow{ - Time: timestamppb.New(entry.Time), - Content: strings.ToValidUTF8(content, "?"), + Time: t, + Content: strings.ToValidUTF8(r.logReplacer.Replace(content), "?"), } } diff --git a/internal/pkg/report/reporter_test.go b/internal/pkg/report/reporter_test.go index 317d63f4..28ac36e6 100644 --- a/internal/pkg/report/reporter_test.go +++ b/internal/pkg/report/reporter_test.go @@ -72,9 +72,12 @@ func TestReporter_parseLogRow(t *testing.T) { "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{ - "GitHub Actions runtime token access controls", + "::debug::GitHub Actions runtime token access controls", + "::debug::first%0Asecond", }, }, { @@ -86,31 +89,46 @@ func TestReporter_parseLogRow(t *testing.T) { "", }, }, + // 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 file=file.name,line=42,endLine=48,title=Cool Title::Gosh, that's not going to work", + "::notice::Gosh, that's not going to work", }, []string{ - "::notice file=file.name,line=42,endLine=48,title=Cool Title::Gosh, that's not going to work", + "::notice::Gosh, that's not going to work", }, }, { "warning", false, []string{ - "::warning file=file.name,line=42,endLine=48,title=Cool Title::Gosh, that's not going to work", + "::warning::Gosh, that's not going to work", }, []string{ - "::warning file=file.name,line=42,endLine=48,title=Cool Title::Gosh, that's not going to work", + "::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=file.name,line=42,endLine=48,title=Cool Title::Gosh, that's not going to work", + "::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", }, }, { @@ -149,6 +167,24 @@ func TestReporter_parseLogRow(t *testing.T) { "*** 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{ @@ -179,6 +215,19 @@ func TestReporter_parseLogRow(t *testing.T) { } } +// 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(&log.Entry{Message: line}), line) + + row := r.parseLogRow(&log.Entry{Message: "using supersecret now"}) + assert.Equal(t, "using *** now", row.Content, line) + } +} + func TestReporter_Fire(t *testing.T) { t.Run("ignore command lines", func(t *testing.T) { client := mocks.NewClient(t) @@ -1013,7 +1062,7 @@ func TestReporter_Result(t *testing.T) { } func TestReporter_SetOutputs(t *testing.T) { - r := &Reporter{state: &runnerv1.TaskState{}} + r := &Reporter{state: &runnerv1.TaskState{}, logReplacer: strings.NewReplacer()} r.SetOutputs(map[string]string{"foo": "bar"}) got, ok := r.outputs["foo"]