Merge pull request 'feat(executor): workflow commands, annotations, matchers, summaries, step timeout (CI-2 G)' (#11) from feat/ci2-commands into main

commit: 86ddb5faa5b098539aaa1b8028f1b5533264237a
author: bnema · 9d ago · 2026-10-14 03:10 UTC
merge of: 6da746a + 41a0ba6 · diff against the first parent
signature: SSH UnverifiedSHA256:VOCA5lYARHcbKDZ7GhTV45VmcjWnJ6ZQIBazj17LivA The key is unknown

36 files · +4989 -197

M README.md +4 -0


@@ -78,6 +78,10 @@ The host name and port come from `ERMITE_RUNNER_URL` (port defaulted from the sc
78		78
79	The host sends a `Cancel{reason}` frame (`execstream.Drive` takes a cancel channel, not a context). The executor signals the script's process group like the official runner: SIGINT at once, SIGTERM after 7.5 s, SIGKILL 2.5 s later, with the timers stopped as soon as the shell exits and nothing signalled afterwards (the group id could be reused). Background children that keep the output pipes open are killed when the shell exits, after a short drain. Init forwards SIGTERM and SIGINT to the executor.	79		The host sends a `Cancel{reason}` frame (`execstream.Drive` takes a cancel channel, not a context). The executor signals the script's process group like the official runner: SIGINT at once, SIGTERM after 7.5 s, SIGKILL 2.5 s later, with the timers stopped as soon as the shell exits and nothing signalled afterwards (the group id could be reused). Background children that keep the output pipes open are killed when the shell exits, after a short drain. Init forwards SIGTERM and SIGINT to the executor.
80		80
		81	+	### Annotations, summaries and masks
		82	+
		83	+	The executor ports the issue handling of the official runner: `::notice`, `::warning` and `::error` (with `title`, `file`, `line`, `endLine`, `col`, `endColumn`), problem matchers (`add-matcher`, `remove-matcher`, .NET regular expressions through `regexp2`, 1 s timeout, `GITHUB_ACTIONS_RUNNER_ISSUE_MATCHER_TIMEOUT`, removed after 3 timeouts) and every `##[error]` the runner itself writes become annotations, at most 10 per level per step, messages cut at 4096 characters; `GITHUB_STEP_SUMMARY` is read after each step (1 MiB). `::add-mask::` adds to the masker at run time, with the encodings of `ValueEncoders.cs`. The executor sends them to the host as `StepAnnotations` and `StepSummary` frames; the host checks the limits again, sends the annotations with the `UpdateJob` that completes the step (the list replaces the step's stored one) and the leftovers with `CompleteJob`, and the summaries with `UploadSummary`. Both are sent only when the server lists `ci.annotations` and `ci.summaries` in `GetVersion` (read once per job). Step `timeout-minutes` is enforced like `StepsRunner` does. Attribution for the ported code and tests: [THIRD_PARTY.md](THIRD_PARTY.md).
		84	+
81	### Cleanup	85		### Cleanup
82		86
83	Everything a job creates (process, TAP or bridge, nftables rules, files, loop mounts, containers, networks, cgroups) is removed by `Stop`, which also runs with a cancelled context, aborts a `Start` in progress, and by `Reap` at start for what a crash left behind. A VM leaves a state record (`<state dir>/vms/<id>.json`) before its first resource. The network policy and the TAP or bridge are never removed while the VMM or the container may still be running: when a process cannot be killed or a container cannot be removed, `Stop` returns an error wrapping `sandbox.ErrLeaked`, the sandbox's slot stays taken, and `Driver.Reap` (which returns `sandbox.ErrBusy` while a sandbox is running) finishes the job and frees the slot. The host should stop taking jobs on a leaked slot until then. `Sandbox.ID()` names a sandbox's files and Docker objects.	87		Everything a job creates (process, TAP or bridge, nftables rules, files, loop mounts, containers, networks, cgroups) is removed by `Stop`, which also runs with a cancelled context, aborts a `Start` in progress, and by `Reap` at start for what a crash left behind. A VM leaves a state record (`<state dir>/vms/<id>.json`) before its first resource. The network policy and the TAP or bridge are never removed while the VMM or the container may still be running: when a process cannot be killed or a container cannot be removed, `Stop` returns an error wrapping `sandbox.ErrLeaked`, the sandbox's slot stays taken, and `Driver.Reap` (which returns `sandbox.ErrBusy` while a sandbox is running) finishes the job and frees the slot. The host should stop taking jobs on a leaked slot until then. `Sandbox.ID()` names a sandbox's files and Docker objects.

A THIRD_PARTY.md +41 -0

@@ -0,0 +1,41 @@
	1	+	# Third-party material
	2	+
	3	+	ermite-runner's executor (`internal/executor`) is a Go port of parts of
	4	+	[actions/runner](https://github.com/actions/runner) (C#), at commit `5f0b3dd`.
	5	+	Texts of messages, limits and the behaviour of the workflow commands, problem
	6	+	matchers, masker and step timeouts are taken from its source, and some unit
	7	+	tests are table versions of its L0 tests:
	8	+
	9	+	\| Test here \| Source test in `src/Test/L0` \|
	10	+	\| --- \| --- \|
	11	+	\| `TestValidateLinesAndColumns` \| `Worker/ActionCommandManagerL0.cs` `IssueCommandInvalidColumns` \|
	12	+	\| `TestMatcherConfigValidate` \| `Worker/IssueMatcherL0.cs` `Config_Validate_*` \|
	13	+	\| `TestMatcherLoopAccumulatesState`, `TestMatcherNonLoop`, `TestMatcherSinglePattern` \| `Worker/IssueMatcherL0.cs` `Matcher_*` \|
	14	+	\| `TestDefaultSecretMaskers`, `TestSecretSectionMasking` \| `HostContextL0.cs` `DefaultSecretMaskers`, `SecretSectionMasking` \|
	15	+	\| `TestAddMaskCommand` \| `Worker/ActionCommandManagerL0.cs` `AddMaskWithMultilineValue` \|
	16	+	\| `TestCatastrophicMatcherIsRemovedAfterThreeTimeouts` \| `Worker/OutputManagerL0.cs` `MatcherTimeout` \|
	17	+
	18	+	actions/runner is licensed under the MIT License:
	19	+
	20	+	The MIT License (MIT)
	21	+	Copyright (c) 2019 GitHub
	22	+
	23	+	Permission is hereby granted, free of charge, to any person obtaining a copy
	24	+	of this software and associated documentation files (the "Software"), to deal
	25	+	in the Software without restriction, including without limitation the rights
	26	+	to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
	27	+	copies of the Software, and to permit persons to whom the Software is
	28	+	furnished to do so, subject to the following conditions:
	29	+
	30	+	The above copyright notice and this permission notice shall be included in all
	31	+	copies or substantial portions of the Software.
	32	+
	33	+	THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
	34	+	IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
	35	+	FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
	36	+	AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
	37	+	LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
	38	+	OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
	39	+	SOFTWARE.
	40	+
	41	+	github.com/dlclark/regexp2 (MIT) is a dependency: a port of the .NET regular expression engine, used for problem matchers.

M go.mod +2 -1

 require (
 	bnema.dev/ermite-actions v0.0.0-20261013040121-5c0e25d50362
-	bnema.dev/ermite-api v0.0.0-20261012155218-f8f64413e63c
+	bnema.dev/ermite-api v0.1.1-0.20261013091642-49ac5fd7a78a
 	connectrpc.com/connect v1.21.0
 	github.com/bnema/zerowrap v1.4.1
 	github.com/containerd/errdefs v1.0.0
+	github.com/dlclark/regexp2 v1.12.0
 	github.com/google/uuid v1.6.0
 	github.com/moby/moby/api v1.56.1
 	github.com/moby/moby/client v0.6.2

M go.sum +4 -2 generated file: collapsed

load diff

M host_cmd.go +1 -0


@@ -159,6 +159,7 @@ func runCmd(ctx context.Context) int {
159	Job: func(tok string) ermiteconnect.RunnerServiceClient {	159		Job: func(tok string) ermiteconnect.RunnerServiceClient {
160	return hcfg.Client(url, tok)	160		return hcfg.Client(url, tok)
161	},	161		},
		162	+	Features: hcfg.ServerFeaturesFunc(url),
162	}	163		}
163	r.Cfg.URL = url	164		r.Cfg.URL = url
164	if err := r.Run(ctx); err != nil {	165		if err := r.Run(ctx); err != nil {

M internal/execstream/exec.proto +47 -0


@@ -25,6 +25,8 @@ message Frame {
25	StepCompleted step_completed = 7; // executor -> host	25		StepCompleted step_completed = 7; // executor -> host
26	Log log = 8; // executor -> host	26		Log log = 8; // executor -> host
27	JobResult job_result = 9; // executor -> host, before Exit	27		JobResult job_result = 9; // executor -> host, before Exit
		28	+	StepAnnotations step_annotations = 10; // executor -> host, before the StepCompleted of the step
		29	+	StepSummary step_summary = 11; // executor -> host, before the StepCompleted of the step
28	}	30		}
29	}	31		}
30		32

@@ -66,6 +68,11 @@ message JobSpec {
66	// executor, and booting the sandbox takes time. 0 means "use	68		// executor, and booting the sandbox takes time. 0 means "use
67	// timeout_minutes from now".	69		// timeout_minutes from now".
68	int64 deadline_ms = 12;	70		int64 deadline_ms = 12;
		71	+	// send_annotations and send_summaries say that the server keeps annotations
		72	+	// (feature ci.annotations) and step summaries (ci.summaries). The executor
		73	+	// sends StepAnnotations and StepSummary frames only when they are set.
		74	+	bool send_annotations = 13;
		75	+	bool send_summaries = 14;
69	}	76		}
70		77
71	enum StreamKind {	78		enum StreamKind {

@@ -117,6 +124,46 @@ message StepCompleted {
117	string name = 2;	124		string name = 2;
118	StepConclusion conclusion = 3;	125		StepConclusion conclusion = 3;
119	int64 unix_nano = 4;	126		int64 unix_nano = 4;
		127	+	// outcome is steps.<id>.outcome: the result before continue-on-error. It
		128	+	// differs from conclusion only for a failed step with continue-on-error.
		129	+	// UNSPECIFIED means the same as conclusion.
		130	+	StepConclusion outcome = 5;
		131	+	}
		132	+
		133	+	enum AnnotationLevel {
		134	+	ANNOTATION_LEVEL_UNSPECIFIED = 0;
		135	+	ANNOTATION_LEVEL_NOTICE = 1;
		136	+	ANNOTATION_LEVEL_WARNING = 2;
		137	+	ANNOTATION_LEVEL_FAILURE = 3;
		138	+	}
		139	+
		140	+	// Annotation is one ::notice, ::warning or ::error (or a problem matcher
		141	+	// match), masked. The host validates every field again before it sends them.
		142	+	message Annotation {
		143	+	AnnotationLevel level = 1;
		144	+	string title = 2;
		145	+	string message = 3;
		146	+	string file = 4; // relative to the repository when the file is in it
		147	+	int32 start_line = 5;
		148	+	int32 end_line = 6;
		149	+	int32 start_column = 7;
		150	+	int32 end_column = 8;
		151	+	}
		152	+
		153	+	// StepAnnotations is the complete list of the annotations of a step (the ones
		154	+	// the runner keeps: at most 10 per level), replacing any earlier list of that
		155	+	// step. Annotations of the steps inside a composite action are those of the
		156	+	// step of the workflow that uses it.
		157	+	message StepAnnotations {
		158	+	int32 step = 1;
		159	+	repeated Annotation annotations = 2;
		160	+	}
		161	+
		162	+	// StepSummary is the masked content of GITHUB_STEP_SUMMARY after a step, at
		163	+	// most 1 MiB.
		164	+	message StepSummary {
		165	+	int32 step = 1;
		166	+	string markdown = 2;
120	}	167		}
121		168
122	enum StepConclusion {	169		enum StepConclusion {

M internal/execstream/execpb/exec.pb.go +431 -65 generated file: collapsed

load diff

M internal/execstream/frame.go +12 -0


@@ -115,6 +115,10 @@ type JobHandler struct {
115	StepCompleted func(*execpb.StepCompleted)	115		StepCompleted func(*execpb.StepCompleted)
116	Log func(*execpb.Log)	116		Log func(*execpb.Log)
117	JobResult func(*execpb.JobResult)	117		JobResult func(*execpb.JobResult)
		118	+	// StepAnnotations and StepSummary come before the StepCompleted of their
		119	+	// step.
		120	+	StepAnnotations func(*execpb.StepAnnotations)
		121	+	StepSummary func(*execpb.StepSummary)
118	}	122		}
119		123
120	// DriveJob is Drive for a session that carries a job: besides Output frames it	124		// DriveJob is Drive for a session that carries a job: besides Output frames it

@@ -179,6 +183,14 @@ func DriveJob(rw io.ReadWriter, run execpb.Run, cancel <-chan execpb.Cancel, h
179	if h.JobResult != nil {	183		if h.JobResult != nil {
180	h.JobResult(b.JobResult)	184		h.JobResult(b.JobResult)
181	}	185		}
		186	+	case *execpb.Frame_StepAnnotations:
		187	+	if h.StepAnnotations != nil {
		188	+	h.StepAnnotations(b.StepAnnotations)
		189	+	}
		190	+	case *execpb.Frame_StepSummary:
		191	+	if h.StepSummary != nil {
		192	+	h.StepSummary(b.StepSummary)
		193	+	}
182	case *execpb.Frame_Exit:	194		case *execpb.Frame_Exit:
183	return hello, b.Exit, nil	195		return hello, b.Exit, nil
184	}	196		}

M internal/executor/commands.go +134 -13


@@ -3,15 +3,17 @@
3		package executor	3		package executor
4			4
5		import (	5		import (
			6	+	"errors"
6		"fmt"	7		"fmt"
			8	+	"io/fs"
			9	+	"os"
			10	+	"path/filepath"
7		"strings"	11		"strings"
8		"unicode"	12		"unicode"
9		)	13		)
10			14
11		// Workflow commands in the output of a step: a port of ActionCommand.cs	15		// Workflow commands in the output of a step: a port of ActionCommand.cs
12	-	// (Runner.Common) and of the parts of ActionCommandManager.cs that CI-1 needs.	16	+	// (Runner.Common) and of ActionCommandManager.cs.
13	-	// Masking (add-mask) and problem matchers are CI-2; they are announced in the
14	-	// log and otherwise ignored.
15			17
16		type escapeMapping struct{ token, replacement string }	18		type escapeMapping struct{ token, replacement string }
17			19

@@ -117,9 +119,7 @@ const (
117		)	119		)
118			120
119		// commandNames are the commands the executor registers, in ActionCommandManager	121		// commandNames are the commands the executor registers, in ActionCommandManager
120	-	// (the names of the extensions at ActionCommandManager.cs). add-mask,	122	+	// (the names of the extensions at ActionCommandManager.cs).
121	-	// add-matcher and remove-matcher are recognised and reported as not supported
122	-	// yet.
123		var commandNames = []string{	123		var commandNames = []string{
124		"set-env", "set-output", "save-state", "add-mask", "add-path", "add-matcher", "remove-matcher",	124		"set-env", "set-output", "save-state", "add-mask", "add-path", "add-matcher", "remove-matcher",
125		"debug", "warning", "error", "notice", "group", "endgroup", "echo", "stop-commands",	125		"debug", "warning", "error", "notice", "group", "endgroup", "echo", "stop-commands",

@@ -139,6 +139,17 @@ type commandHost interface {
139		CommandFailed()	139		CommandFailed()
140		// EnvFlag reads a variable of the env context, then of the process.	140		// EnvFlag reads a variable of the env context, then of the process.
141		EnvFlag(name string) bool	141		EnvFlag(name string) bool
			142	+	// AddIssue is ExecutionContext.AddIssue: it logs the issue and keeps it for
			143	+	// the annotations of the step.
			144	+	AddIssue(issue)
			145	+	// Workspace is github.workspace.
			146	+	Workspace() string
			147	+	// AddMask is SecretMasker.AddValue.
			148	+	AddMask(value string)
			149	+	// Matchers is the root of the problem matchers of the job.
			150	+	Matchers() *matcherRoot
			151	+	// ReadMatcherFile reads a problem matcher file (IOUtil.LoadObject).
			152	+	ReadMatcherFile(path string) ([]byte, error)
142		}	153		}
143			154
144		// commandManager is ActionCommandManager: one per step.	155		// commandManager is ActionCommandManager: one per step.

@@ -192,6 +203,9 @@ func (m *commandManager) TryProcess(input string) bool {
192		}	203		}
193		m.stopToken, m.stopped = cmd.Data, true	204		m.stopToken, m.stopped = cmd.Data, true
194		m.registered[strings.ToLower(cmd.Data)] = true	205		m.registered[strings.ToLower(cmd.Data)] = true
			206	+	if len(m.stopToken) > 6 { // ActionCommandManager.cs:117
			207	+	m.host.AddMask(m.stopToken)
			208	+	}
195		m.host.Out(input)	209		m.host.Out(input)
196		m.host.Debug("Paused processing commands until the token you called ::stopCommands:: with is received")	210		m.host.Debug("Paused processing commands until the token you called ::stopCommands:: with is received")
197		return true	211		return true

@@ -233,10 +247,12 @@ func (m commandManager) run(name string, c actionCommand) error {
233		h.Out("##[endgroup]")	247		h.Out("##[endgroup]")
234		case "debug":	248		case "debug":
235		h.Debug(c.Data)	249		h.Debug(c.Data)
236	-	case "warning", "error", "notice":	250	+	case "warning":
237	-	// IssueCommandExtension: the annotation is logged; ermite does not store	251	+	m.commandIssue(LevelWarning, name, c)
238	-	// annotations yet (CI-2), so file, line and title are dropped.	252	+	case "error":
239	-	h.Tagged("##["+name+"]", c.Data)	253	+	m.commandIssue(LevelFailure, name, c)
			254	+	case "notice":
			255	+	m.commandIssue(LevelNotice, name, c)
240		case "echo":	256		case "echo":
241		if c.Data == "" {	257		if c.Data == "" {
242		return ghErrorf("Value cannot be null or empty. (Parameter 'value')")	258		return ghErrorf("Value cannot be null or empty. (Parameter 'value')")

@@ -289,9 +305,114 @@ func (m commandManager) run(name string, c actionCommand) error {
289		return ghErrorf("Value cannot be null or empty. (Parameter 'path')")	305		return ghErrorf("Value cannot be null or empty. (Parameter 'path')")
290		}	306		}
291		h.AddPath(c.Data)	307		h.AddPath(c.Data)
292	-	case "add-mask", "add-matcher", "remove-matcher":	308	+	case "add-mask":
293	-	// Not supported yet (CI-2). The value of add-mask is not echoed.	309	+	m.addMask(c)
294	-	h.Tagged("##[warning]", fmt.Sprintf("The `%s` command is not supported yet by this runner.", name))	310	+	case "add-matcher":
			311	+	return m.addMatcher(c)
			312	+	case "remove-matcher":
			313	+	return m.removeMatcher(c)
			314	+	}
			315	+	return nil
			316	+	}
			317	+
			318	+	// warn is IExecutionContext.Warning.
			319	+	func (m *commandManager) warn(msg string) { m.host.AddIssue(issue{Level: LevelWarning, Message: msg}) }
			320	+
			321	+	// addMask is AddMaskCommandExtension (ActionCommandManager.cs:402-424).
			322	+	func (m commandManager) addMask(c actionCommand) {
			323	+	if strings.TrimFunc(c.Data, unicode.IsSpace) == "" {
			324	+	m.warn("Can't add secret mask for empty string in ##[add-mask] command.")
			325	+	return
			326	+	}
			327	+	if m.echo {
			328	+	m.host.Out("::add-mask::***")
			329	+	}
			330	+	m.host.AddMask(c.Data)
			331	+	// Also add each individual line. Typically individual lines are processed
			332	+	// from STDOUT of child processes.
			333	+	for _, item := range strings.FieldsFunc(c.Data, func(r rune) bool { return r == '\r' \|\| r == '\n' }) {
			334	+	if item = strings.TrimFunc(item, unicode.IsSpace); item != "" {
			335	+	m.host.AddMask(item)
			336	+	}
			337	+	}
			338	+	}
			339	+
			340	+	// matcherPath roots a path of add-matcher and remove-matcher in the workspace.
			341	+	func (m *commandManager) matcherPath(file string) string {
			342	+	if !filepath.IsAbs(file) {
			343	+	return filepath.Join(m.host.Workspace(), file)
			344	+	}
			345	+	return file
			346	+	}
			347	+
			348	+	// loadMatchers is IOUtil.LoadObject<IssueMatchersConfig>.
			349	+	func (m commandManager) loadMatchers(file string) (matchersConfig, error) {
			350	+	b, err := m.host.ReadMatcherFile(file)
			351	+	if err != nil {
			352	+	return nil, dotnetFileError(file, err)
			353	+	}
			354	+	return parseMatchersConfig(b)
			355	+	}
			356	+
			357	+	// dotnetFileError gives the error of a file that cannot be read the text of
			358	+	// the .NET exception (FileNotFoundException, DirectoryNotFoundException).
			359	+	func dotnetFileError(file string, err error) error {
			360	+	switch {
			361	+	case errors.Is(err, fs.ErrNotExist):
			362	+	if st, e := os.Stat(filepath.Dir(file)); e != nil \|\| !st.IsDir() {
			363	+	return ghErrorf("Could not find a part of the path '%s'.", file)
			364	+	}
			365	+	return ghErrorf("Could not find file '%s'.", file)
			366	+	case errors.Is(err, fs.ErrPermission):
			367	+	return ghErrorf("Access to the path '%s' is denied.", file)
			368	+	}
			369	+	return err
			370	+	}
			371	+
			372	+	// addMatcher is AddMatcherCommandExtension (ActionCommandManager.cs:496-536).
			373	+	func (m commandManager) addMatcher(c actionCommand) error {
			374	+	if c.Data == "" {
			375	+	m.warn("File path must be specified.")
			376	+	return nil
			377	+	}
			378	+	cfg, err := m.loadMatchers(m.matcherPath(c.Data))
			379	+	if err != nil {
			380	+	return err
			381	+	}
			382	+	if cfg != nil && len(cfg.Matchers) > 0 {
			383	+	if err := cfg.validate(); err != nil {
			384	+	return err
			385	+	}
			386	+	m.host.Debug(m.host.Matchers().add(cfg))
			387	+	}
			388	+	return nil
			389	+	}
			390	+
			391	+	// removeMatcher is RemoveMatcherCommandExtension (ActionCommandManager.cs:538-607).
			392	+	func (m commandManager) removeMatcher(c actionCommand) error {
			393	+	owner, file := c.prop("owner"), c.Data
			394	+	if owner != "" && file != "" {
			395	+	m.warn("Either specify an owner name or a file path in ##[remove-matcher] command. Both values cannot be set.")
			396	+	return nil
			397	+	}
			398	+	if owner == "" && file == "" {
			399	+	m.warn("Either an owner name or a file path must be specified in ##[remove-matcher] command.")
			400	+	return nil
			401	+	}
			402	+	if owner != "" {
			403	+	m.host.Debug(m.host.Matchers().remove([]string{owner}))
			404	+	return nil
			405	+	}
			406	+	cfg, err := m.loadMatchers(m.matcherPath(file))
			407	+	if err != nil {
			408	+	return err
			409	+	}
			410	+	if cfg != nil && len(cfg.Matchers) > 0 {
			411	+	var owners []string
			412	+	for _, mc := range cfg.Matchers {
			413	+	owners = append(owners, mc.Owner)
			414	+	}
			415	+	m.host.Debug(m.host.Matchers().remove(owners))
295		}	416		}
296		return nil	417		return nil
297		}	418		}

M internal/executor/exec_step.go +4 -10

 // step.
 func (j *job) startProcess(s *stepRun, plan ShellPlan, dir string, argv []string, stepCancel <-chan struct{}) stepResult {
 	num := s.num
+	om := newOutputManager(s, stepCancel)
+	defer om.dispose()
 	res, err := runProcess(procSpec{
 		Argv: argv, Dir: dir, Env: j.processEnv(s.env), Credential: j.cfg.Credential,
-		OnLine: func(line string) {
+		OnLine: om.onData,
-			if strings.Contains(line, "##[start-action") || strings.Contains(line, "##[end-action") {
-				line = strings.ReplaceAll(strings.ReplaceAll(line, "##[start-action", `##[\start-action`), "##[end-action", `##[\end-action`)
-			}
-			if (strings.Contains(line, "##[") || strings.Contains(line, "::")) && s.cmds.TryProcess(line) {
-				return
-			}
-			j.write(num, line)
-		},
 		Cancel: stepCancel, TermAfter: j.cfg.TermAfter, KillAfter: j.cfg.KillAfter,
 		WaitDelay: j.cfg.WaitDelay, Signal: j.cfg.Signal,
 	})
 		// The process was stopped on cancellation: ExecuteAsync throws
 		// (ProcessInvoker.cs:369) and StepsRunner logs the exception
 		// (StepsRunner.cs:333-337).
-		j.errorf(num, "The operation was canceled.")
+		s.logCanceled()
 		return resCanceled
 	}
 	if res.ExitCode != 0 {

M internal/executor/filecmd.go +53 -6


@@ -238,11 +238,17 @@ func readText(root *os.Root, name string) (text string, ok bool, err error) {
238		if err != nil {	238		if err != nil {
239		return "", false, err	239		return "", false, err
240		}	240		}
			241	+	return decodeText(b), true, nil
			242	+	}
			243	+
			244	+	// decodeText is the decoding of File.ReadAllText: a UTF-8 BOM is dropped and
			245	+	// invalid bytes become U+FFFD.
			246	+	func decodeText(b []byte) string {
241		b = bytes.TrimPrefix(b, []byte("\xef\xbb\xbf"))	247		b = bytes.TrimPrefix(b, []byte("\xef\xbb\xbf"))
242		if !utf8.Valid(b) {	248		if !utf8.Valid(b) {
243		b = bytes.ToValidUTF8(b, []byte("\ufffd"))	249		b = bytes.ToValidUTF8(b, []byte("\ufffd"))
244		}	250		}
245	-	return string(b), true, nil	251	+	return string(b)
246		}	252		}
247			253
248		// createExcl creates name in root with the content, failing if it exists (an	254		// createExcl creates name in root with the content, failing if it exists (an

@@ -354,9 +360,14 @@ func readEnvFile(sink Sink, root *os.Root, name string) ([]Pair, error) {
354		return ParseEnvFile(text)	360		return ParseEnvFile(text)
355		}	361		}
356			362
357	-	// processStepSummary is CreateStepSummaryCommand.ProcessCommand (:230) for	363	+	// afterSummaryStat is called between the size check of the summary and its
358	-	// CI-1: the file is only checked (an empty file is ignored, a file above 1 MiB	364	+	// read; tests use it to make the file grow.
359	-	// is an error); ermite does not store summaries yet.	365	+	var afterSummaryStat func()
			366	+
			367	+	// processStepSummary is CreateStepSummaryCommand.ProcessCommand
			368	+	// (FileCommandManager.cs:230-275): a missing or empty file is ignored, a file
			369	+	// above 1 MiB is an error; otherwise the lines are masked one by one and the
			370	+	// result goes to the sink when it keeps summaries. mask may be nil.
360		func processStepSummary(sink Sink, root *os.Root, name string) error {	371		func processStepSummary(sink Sink, root *os.Root, name string) error {
361		fh, err := openRegular(root, name)	372		fh, err := openRegular(root, name)
362		if errors.Is(err, os.ErrNotExist) {	373		if errors.Is(err, os.ErrNotExist) {

@@ -365,14 +376,50 @@ func processStepSummary(sink Sink, root *os.Root, name string) error {
365		if err != nil {	376		if err != nil {
366		return err	377		return err
367		}	378		}
			379	+	defer func() { _ = fh.Close() }()
368		st, err := fh.Stat()	380		st, err := fh.Stat()
369	-	_ = fh.Close()
370		if err != nil \|\| st.Size() == 0 {	381		if err != nil \|\| st.Size() == 0 {
371		return nil	382		return nil
372		}	383		}
			384	+	tooLarge := func(size int64) {
			385	+	sink.Error(fmt.Sprintf("$GITHUB_STEP_SUMMARY upload aborted, supports content up to a size of %dk, got %dk. For more information see: https://docs.github.com/actions/using-workflows/workflow-commands-for-github-actions#adding-a-markdown-summary", stepSummaryLimit/1024, size/1024))
			386	+	}
373		if st.Size() > stepSummaryLimit {	387		if st.Size() > stepSummaryLimit {
374	-	sink.Error(fmt.Sprintf("$GITHUB_STEP_SUMMARY upload aborted, supports content up to a size of %dk, got %dk. For more information see: https://docs.github.com/actions/using-workflows/workflow-commands-for-github-actions#adding-a-markdown-summary", stepSummaryLimit/1024, st.Size()/1024))	388	+	tooLarge(st.Size())
			389	+	return nil
			390	+	}
			391	+	ss, ok := sink.(summarySink)
			392	+	if !ok {
			393	+	return nil
			394	+	}
			395	+	if afterSummaryStat != nil {
			396	+	afterSummaryStat()
			397	+	}
			398	+	// The file belongs to the user of the step, who can still write to it (a
			399	+	// background process of the step): what is read is bounded by the limit on
			400	+	// the descriptor that was checked, not by the size seen a moment ago.
			401	+	b, err := io.ReadAll(io.LimitReader(fh, stepSummaryLimit+1))
			402	+	if err != nil {
			403	+	return err
			404	+	}
			405	+	if len(b) > stepSummaryLimit {
			406	+	tooLarge(int64(len(b)))
			407	+	return nil
			408	+	}
			409	+	text := decodeText(b)
			410	+	var mask func(string) string
			411	+	if m, has := sink.(interface{ MaskText(string) string }); has {
			412	+	mask = m.MaskText
			413	+	} else {
			414	+	mask = func(s string) string { return s }
			415	+	}
			416	+	content := summaryContent(text, mask)
			417	+	if len(content) > stepSummaryLimit {
			418	+	// Masking made it longer than the limit of the contract.
			419	+	tooLarge(int64(len(content)))
			420	+	return nil
375		}	421		}
			422	+	ss.Summary(content)
376		return nil	423		return nil
377		}	424		}
378			425

M internal/executor/filecmd_test.go +39 -0


@@ -379,3 +379,42 @@ func TestCreateExclChownsTheOpenFile(t *testing.T) {
379	}	379		}
380	}	380		}
381	}	381		}
		382	+
		383	+	// The summary is read from the descriptor that was checked, at most the limit
		384	+	// plus one byte: a file that grows after the size check (a background process
		385	+	// of the step) cannot make the executor read it whole (GO-005).
		386	+	func TestStepSummaryGrowingAfterTheSizeCheckIsBounded(t *testing.T) {
		387	+	fc, _ := NewFileCommands(t.TempDir())
		388	+	env, _ := fc.Init()
		389	+	path := env["GITHUB_STEP_SUMMARY"]
		390	+	if err := os.WriteFile(path, []byte("small\n"), 0o644); err != nil {
		391	+	t.Fatal(err)
		392	+	}
		393	+	afterSummaryStat = func() {
		394	+	f, err := os.OpenFile(path, os.O_WRONLY\|os.O_APPEND, 0)
		395	+	if err != nil {
		396	+	t.Error(err)
		397	+	return
		398	+	}
		399	+	defer func() { _ = f.Close() }()
		400	+	if _, err := f.Write(make([]byte, 8<<20)); err != nil {
		401	+	t.Error(err)
		402	+	}
		403	+	}
		404	+	t.Cleanup(func() { afterSummaryStat = nil })
		405	+	s := &summarySinkFake{fakeSink: newSink()}
		406	+	fc.Process(s)
		407	+	if s.got != "" {
		408	+	t.Errorf("a summary of %d bytes was kept", len(s.got))
		409	+	}
		410	+	if len(s.errors) != 1 \|\| !strings.HasPrefix(s.errors[0], "$GITHUB_STEP_SUMMARY upload aborted, supports content up to a size of 1024k, got 1024k.") {
		411	+	t.Fatalf("%q", s.errors)
		412	+	}
		413	+	}
		414	+
		415	+	type summarySinkFake struct {
		416	+	*fakeSink
		417	+	got string
		418	+	}
		419	+
		420	+	func (s *summarySinkFake) Summary(m string) { s.got = m }

A internal/executor/issues.go +298 -0

@@ -0,0 +1,298 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"fmt"
	7	+	"strconv"
	8	+	"strings"
	9	+	"sync"
	10	+	"unicode/utf8"
	11	+	)
	12	+
	13	+	// Annotations: a port of the issue handling of the official runner,
	14	+	// ExecutionContext.AddIssue (ExecutionContext.cs:796) and
	15	+	// IssueCommandExtension (ActionCommandManager.cs:660-770).
	16	+
	17	+	const (
	18	+	// maxCountPerIssueType is ExecutionContext._maxCountPerIssueType.
	19	+	maxCountPerIssueType = 10
	20	+	// Limits of the contract (runner.proto, Annotation): the server refuses a
	21	+	// whole call that exceeds them, so the executor keeps within them.
	22	+	maxAnnotationTitle = 255
	23	+	maxAnnotationFile = 1024
	24	+	)
	25	+
	26	+	// issue is what AddIssue receives (DTWebApi.Issue and the log options).
	27	+	type issue struct {
	28	+	Level AnnotationLevel
	29	+	Message string
	30	+	// Props are the Data of the issue: title, file, line, endline, col,
	31	+	// endcolumn (keys in lower case), as the commands and matchers set them.
	32	+	Props map[string]string
	33	+	// LogText replaces the message in the log (ExecutionContextLogOptions
	34	+	// .LogMessageOverride, set by problem matchers).
	35	+	LogText string
	36	+	}
	37	+
	38	+	func tagOf(l AnnotationLevel) string {
	39	+	switch l {
	40	+	case LevelFailure:
	41	+	return "##[error]"
	42	+	case LevelWarning:
	43	+	return "##[warning]"
	44	+	}
	45	+	return "##[notice]"
	46	+	}
	47	+
	48	+	func levelOfTag(tag string) (AnnotationLevel, bool) {
	49	+	switch tag {
	50	+	case "##[error]":
	51	+	return LevelFailure, true
	52	+	case "##[warning]":
	53	+	return LevelWarning, true
	54	+	case "##[notice]":
	55	+	return LevelNotice, true
	56	+	}
	57	+	return "", false
	58	+	}
	59	+
	60	+	// issueCollector keeps the annotations of one step of the workflow, which is
	61	+	// what the server stores them under. The steps inside a composite action
	62	+	// (embedded contexts) add to the collector of the step that uses the action:
	63	+	// like the runner, their issues are held back and only counted against the
	64	+	// limit of ten per level when the outer step completes
	65	+	// (ExecutionContext.Complete, :528-540).
	66	+	type issueCollector struct {
	67	+	mu sync.Mutex
	68	+	own []Annotation
	69	+	counts map[AnnotationLevel]int
	70	+	embedded []Annotation
	71	+	}
	72	+
	73	+	func newIssueCollector() *issueCollector {
	74	+	return &issueCollector{counts: map[AnnotationLevel]int{}}
	75	+	}
	76	+
	77	+	func (c *issueCollector) add(a Annotation, embedded bool) {
	78	+	c.mu.Lock()
	79	+	defer c.mu.Unlock()
	80	+	if embedded {
	81	+	c.embedded = append(c.embedded, a)
	82	+	return
	83	+	}
	84	+	c.addLocked(a)
	85	+	}
	86	+
	87	+	func (c *issueCollector) addLocked(a Annotation) {
	88	+	if c.counts[a.Level] < maxCountPerIssueType {
	89	+	c.counts[a.Level]++
	90	+	c.own = append(c.own, a)
	91	+	}
	92	+	}
	93	+
	94	+	// result returns the annotations of the step: its own, then those of the
	95	+	// embedded steps within what is left of the limits.
	96	+	func (c *issueCollector) result() []Annotation {
	97	+	c.mu.Lock()
	98	+	defer c.mu.Unlock()
	99	+	for _, a := range c.embedded {
	100	+	c.addLocked(a)
	101	+	}
	102	+	c.embedded = nil
	103	+	return append([]Annotation(nil), c.own...)
	104	+	}
	105	+
	106	+	// collector returns the collector of a step of the workflow.
	107	+	func (j job) collector(num int) issueCollector {
	108	+	j.issuesMu.Lock()
	109	+	defer j.issuesMu.Unlock()
	110	+	if j.collectors == nil {
	111	+	j.collectors = map[int]*issueCollector{}
	112	+	}
	113	+	c := j.collectors[num]
	114	+	if c == nil {
	115	+	c = newIssueCollector()
	116	+	j.collectors[num] = c
	117	+	}
	118	+	return c
	119	+	}
	120	+
	121	+	// truncateUTF16 cuts s to n UTF-16 code units, the unit of .NET's
	122	+	// Substring(0, n), without splitting a character.
	123	+	func truncateUTF16(s string, n int) string {
	124	+	units := 0
	125	+	for i, r := range s {
	126	+	w := 1
	127	+	if r >= 0x10000 {
	128	+	w = 2
	129	+	}
	130	+	if units+w > n {
	131	+	return s[:i]
	132	+	}
	133	+	units += w
	134	+	}
	135	+	return s
	136	+	}
	137	+
	138	+	func truncateRunes(s string, n int) string {
	139	+	if utf8.RuneCountInString(s) <= n {
	140	+	return s
	141	+	}
	142	+	i := 0
	143	+	for k := range s {
	144	+	if i == n {
	145	+	return s[:k]
	146	+	}
	147	+	i++
	148	+	}
	149	+	return s
	150	+	}
	151	+
	152	+	// addIssue is ExecutionContext.AddIssue: the message is masked and cut to
	153	+	// 4096 characters, the issue is kept for the annotations of the step (at most
	154	+	// ten per level) and written to the log.
	155	+	func (j job) addIssue(num int, c issueCollector, embedded bool, is issue) {
	156	+	msg := j.mask(is.Message)
	157	+	msg = truncateUTF16(msg, maxIssueMessageLength)
	158	+	if c == nil {
	159	+	c = j.collector(num)
	160	+	}
	161	+	if msg != "" {
	162	+	c.add(j.annotationOf(is, msg), embedded)
	163	+	}
	164	+	logMsg := msg
	165	+	if is.LogText != "" {
	166	+	logMsg = j.mask(is.LogText)
	167	+	}
	168	+	if logMsg != "" { // an empty message is not logged (:855)
	169	+	j.logTagged(num, tagOf(is.Level), logMsg)
	170	+	}
	171	+	}
	172	+
	173	+	// logTagged writes tag+message; only the first line carries the tag.
	174	+	func (j *job) logTagged(num int, tag, msg string) {
	175	+	lines := strings.Split(strings.ReplaceAll(msg, "\r\n", "\n"), "\n")
	176	+	j.write(num, tag+lines[0])
	177	+	for _, l := range lines[1:] {
	178	+	j.write(num, l)
	179	+	}
	180	+	}
	181	+
	182	+	// parseInt is int.TryParse(string, out int): white space around, an optional
	183	+	// sign, digits, within 32 bits.
	184	+	func parseInt(s string) (int, bool) {
	185	+	n, err := strconv.ParseInt(strings.TrimSpace(s), 10, 32)
	186	+	return int(n), err == nil
	187	+	}
	188	+
	189	+	// annotationOf converts an issue to the Annotation of the contract. The
	190	+	// runner puts the properties in Issue.Data and lets the service build the
	191	+	// check annotation; negative or non numeric numbers cannot be sent, and are
	192	+	// left out. The title and the file are masked too (the runner masks only the
	193	+	// message).
	194	+	func (j *job) annotationOf(is issue, msg string) Annotation {
	195	+	a := Annotation{Level: is.Level, Message: msg}
	196	+	p := is.Props
	197	+	a.Title = truncateRunes(j.mask(p["title"]), maxAnnotationTitle)
	198	+	if f := j.mask(p["file"]); utf8.RuneCountInString(f) <= maxAnnotationFile {
	199	+	a.File = f
	200	+	}
	201	+	num := func(k string) int32 {
	202	+	if n, ok := parseInt(p[k]); ok && n > 0 {
	203	+	return int32(n)
	204	+	}
	205	+	return 0
	206	+	}
	207	+	a.StartLine, a.EndLine = num("line"), num("endline")
	208	+	a.StartColumn, a.EndColumn = num("col"), num("endcolumn")
	209	+	if a.EndLine != 0 && a.EndLine < a.StartLine {
	210	+	a.EndLine = 0
	211	+	}
	212	+	return a
	213	+	}
	214	+
	215	+	// validateLinesAndColumns is IssueCommandExtension.ValidateLinesAndColumns
	216	+	// (ActionCommandManager.cs:731-785). props has lower-case keys; command is the
	217	+	// name in the debug messages.
	218	+	func validateLinesAndColumns(props map[string]string, command string, debug func(string)) {
	219	+	line, endLine, column, endColumn := props["line"], props["endline"], props["col"], props["endcolumn"]
	220	+	lineNumber, hasStartLine := parseInt(line)
	221	+	endLineNumber, hasEndLine := parseInt(endLine)
	222	+	columnNumber, hasStartColumn := parseInt(column)
	223	+	endColumnNumber, hasEndColumn := parseInt(endColumn)
	224	+	hasColumn := hasStartColumn \|\| hasEndColumn
	225	+	msg := func(f string, a ...any) {
	226	+	debug(fmt.Sprintf("Invalid %s command value. ", command) + fmt.Sprintf(f, a...))
	227	+	}
	228	+
	229	+	if hasEndLine && !hasStartLine {
	230	+	msg("'endLine' can only be set if 'line' is provided")
	231	+	props["line"] = endLine
	232	+	hasStartLine = true
	233	+	line = endLine
	234	+	lineNumber = endLineNumber
	235	+	}
	236	+	if hasEndColumn && !hasStartColumn {
	237	+	msg("'endColumn' can only be set if 'col' is provided")
	238	+	props["col"] = endColumn
	239	+	hasStartColumn = true
	240	+	column = endColumn
	241	+	columnNumber = endColumnNumber
	242	+	}
	243	+	if !hasStartLine && hasColumn {
	244	+	msg("'col' and 'endColumn' can only be set if 'line' value is provided.")
	245	+	delete(props, "col")
	246	+	delete(props, "endcolumn")
	247	+	}
	248	+	if hasEndLine && line != endLine && hasColumn {
	249	+	msg("'col' and 'endColumn' cannot be set if 'line' and 'endLine' are different values.")
	250	+	delete(props, "col")
	251	+	delete(props, "endcolumn")
	252	+	}
	253	+	if hasStartLine && hasEndLine && endLineNumber < lineNumber {
	254	+	msg("'endLine' cannot be less than 'line'.")
	255	+	delete(props, "line")
	256	+	delete(props, "endline")
	257	+	}
	258	+	if hasStartColumn && hasEndColumn && endColumnNumber < columnNumber {
	259	+	msg("'endColumn' cannot be less than 'col'.")
	260	+	delete(props, "col")
	261	+	delete(props, "endcolumn")
	262	+	}
	263	+	_ = column
	264	+	}
	265	+
	266	+	// makeRelative is IOUtil.MakeRelative on Linux: path relative to folder when
	267	+	// folder is a prefix of it at a directory boundary, else path unchanged.
	268	+	func makeRelative(path, folder string) string {
	269	+	if !strings.HasPrefix(path, folder) {
	270	+	return path
	271	+	}
	272	+	if len(path) == len(folder) {
	273	+	return ""
	274	+	}
	275	+	if folder != "" && folder[len(folder)-1] == '/' {
	276	+	return path[len(folder):]
	277	+	}
	278	+	if path[len(folder)] == '/' {
	279	+	return path[len(folder)+1:]
	280	+	}
	281	+	return path
	282	+	}
	283	+
	284	+	// commandIssue is IssueCommandExtension.ProcessCommand.
	285	+	func (m commandManager) commandIssue(level AnnotationLevel, name string, c actionCommand) {
	286	+	h := m.host
	287	+	props := map[string]string{}
	288	+	for k, v := range c.Props {
	289	+	props[k] = v
	290	+	}
	291	+	validateLinesAndColumns(props, name, h.Debug)
	292	+	if file := props["file"]; file != "" {
	293	+	if rel := makeRelative(file, h.Workspace()); rel != file && rel != "" {
	294	+	props["file"] = rel
	295	+	}
	296	+	}
	297	+	h.AddIssue(issue{Level: level, Message: c.Data, Props: props})
	298	+	}

A internal/executor/issues_test.go +226 -0

@@ -0,0 +1,226 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"fmt"
	7	+	"strings"
	8	+	"sync"
	9	+	"testing"
	10	+	)
	11	+
	12	+	// resultRecorder is a recorder that also keeps StepResults.
	13	+	type resultRecorder struct {
	14	+	*recorder
	15	+	rmu sync.Mutex
	16	+	results map[int]StepResults
	17	+	}
	18	+
	19	+	func newResultRecorder() *resultRecorder {
	20	+	return &resultRecorder{recorder: newRecorder(), results: map[int]StepResults{}}
	21	+	}
	22	+
	23	+	func (r *resultRecorder) StepResults(n int, res StepResults) {
	24	+	r.rmu.Lock()
	25	+	defer r.rmu.Unlock()
	26	+	r.results[n] = res
	27	+	}
	28	+
	29	+	func runResults(t testing.T, yaml string, tweak func(Config)) (*resultRecorder, Result) {
	30	+	t.Helper()
	31	+	rr := newResultRecorder()
	32	+	// The recorder is wrapped: Reporter methods come from recorder, StepResults
	33	+	// from resultRecorder.
	34	+	_, res := runLocal(t, yaml, "j", func(c *Config) {
	35	+	c.Reporter = rr
	36	+	c.SendAnnotations, c.SendSummaries = true, true
	37	+	if tweak != nil {
	38	+	tweak(c)
	39	+	}
	40	+	})
	41	+	return rr, res
	42	+	}
	43	+
	44	+	// Cases of ActionCommandManagerL0.IssueCommandInvalidColumns (actions/runner,
	45	+	// MIT), as a table: the properties after ValidateLinesAndColumns.
	46	+	func TestValidateLinesAndColumns(t *testing.T) {
	47	+	reg := func(string) bool { return true }
	48	+	for _, tc := range []struct {
	49	+	name, cmd string
	50	+	want map[string]string
	51	+	}{
	52	+	{"columns when lines differ", "::warning line=1,endLine=2,col=1,endColumn=2::m", map[string]string{"line": "1", "endline": "2"}},
	53	+	{"no lines with columns", "::warning col=1,endColumn=2::m", map[string]string{}},
	54	+	{"no line with endLine", "::warning endLine=1::m", map[string]string{"line": "1", "endline": "1"}},
	55	+	{"no column with endColumn", "::warning line=1,endColumn=2::m", map[string]string{"line": "1", "col": "2", "endcolumn": "2"}},
	56	+	{"empty strings", "::warning line=,endLine=3::m", map[string]string{"line": "3", "endline": "3"}},
	57	+	{"end line before line", "::warning line=4,endLine=3::m", map[string]string{}},
	58	+	{"end column before column", "::warning line=1,endLine=1,col=3,endColumn=2::m", map[string]string{"line": "1", "endline": "1"}},
	59	+	{"valid", "::warning line=1,endLine=1,col=1,endColumn=2::m", map[string]string{"line": "1", "endline": "1", "col": "1", "endcolumn": "2"}},
	60	+	{"backwards compatibility", "::warning line=1,col=1,file=test.txt::m", map[string]string{"line": "1", "col": "1", "file": "test.txt"}},
	61	+	} {
	62	+	c, ok := parseCommandV2(tc.cmd, reg)
	63	+	if !ok {
	64	+	t.Fatalf("%s: not parsed", tc.name)
	65	+	}
	66	+	props := map[string]string{}
	67	+	for k, v := range c.Props {
	68	+	props[k] = v
	69	+	}
	70	+	validateLinesAndColumns(props, "warning", func(string) {})
	71	+	if fmt.Sprint(props) != fmt.Sprint(tc.want) {
	72	+	t.Errorf("%s: %v, want %v", tc.name, props, tc.want)
	73	+	}
	74	+	}
	75	+	}
	76	+
	77	+	func TestAnnotationsFromCommands(t *testing.T) {
	78	+	needTools(t, "bash")
	79	+	rr, res := runResults(t, wfHead+` steps:
	80	+	- run: \|
	81	+	echo "::warning title=T,file=src/a.go,line=3,endLine=5,col=1,endColumn=2::careful"
	82	+	echo "::error::broken%0Aline two"
	83	+	echo "::notice::fyi"
	84	+	`, nil)
	85	+	if res.Conclusion != ConclusionSuccess {
	86	+	t.Fatalf("%+v", res)
	87	+	}
	88	+	got := rr.results[2].Annotations
	89	+	want := []Annotation{
	90	+	{Level: LevelWarning, Title: "T", Message: "careful", File: "src/a.go", StartLine: 3, EndLine: 5},
	91	+	{Level: LevelFailure, Message: "broken\nline two"},
	92	+	{Level: LevelNotice, Message: "fyi"},
	93	+	}
	94	+	// col and endColumn are dropped because the lines differ.
	95	+	if fmt.Sprint(got) != fmt.Sprint(want) {
	96	+	t.Errorf("annotations\n got %+v\nwant %+v", got, want)
	97	+	}
	98	+	log := logOf(rr.step(t, "Run echo \"::warning title=T,file=src/a.go,line=3,endLine=5,col=1,endColumn=2::careful\""))
	99	+	for _, w := range []string{"##[warning]careful", "##[error]broken\nline two", "##[notice]fyi"} {
	100	+	if !strings.Contains(log, w) {
	101	+	t.Errorf("log lacks %q:\n%s", w, log)
	102	+	}
	103	+	}
	104	+	}
	105	+
	106	+	// ExecutionContext.cs:144-146: ten per level per step, messages of 4096
	107	+	// characters at most; the rest only reaches the log.
	108	+	func TestAnnotationLimits(t *testing.T) {
	109	+	needTools(t, "bash")
	110	+	rr, _ := runResults(t, wfHead+` steps:
	111	+	- name: many
	112	+	run: \|
	113	+	for i in $(seq 1 12); do
	114	+	echo "::warning::w$i"; echo "::error::e$i"; echo "::notice::n$i"
	115	+	done
	116	+	- name: long
	117	+	run: \|
	118	+	printf '::warning::%s\n' "$(head -c 5000 /dev/zero \| tr '\0' x)"
	119	+	`, nil)
	120	+	count := map[AnnotationLevel]int{}
	121	+	for _, a := range rr.results[2].Annotations {
	122	+	count[a.Level]++
	123	+	}
	124	+	if count[LevelWarning] != 10 \|\| count[LevelFailure] != 10 \|\| count[LevelNotice] != 10 {
	125	+	t.Errorf("counts %v", count)
	126	+	}
	127	+	if a := rr.results[2].Annotations; a[len(a)-1].Message == "w12" {
	128	+	t.Error("the eleventh was kept")
	129	+	}
	130	+	log := logOf(rr.step(t, "many"))
	131	+	if !strings.Contains(log, "##[warning]w12") \|\| !strings.Contains(log, "##[error]e12") {
	132	+	t.Error("annotations over the limit are still logged")
	133	+	}
	134	+	long := rr.results[3].Annotations
	135	+	if len(long) != 1 \|\| len(long[0].Message) != 4096 {
	136	+	t.Errorf("long message: %d annotations, len %d", len(long), len(long[0].Message))
	137	+	}
	138	+	if l := logOf(rr.step(t, "long")); !strings.Contains(l, "##[warning]"+strings.Repeat("x", 4096)+"\n") && !strings.HasSuffix(l, "##[warning]"+strings.Repeat("x", 4096)) {
	139	+	t.Error("the log has the message cut to 4096 characters")
	140	+	}
	141	+	}
	142	+
	143	+	// Every ##[error] the runner itself writes is an issue and an annotation.
	144	+	func TestRunnerErrorsAreAnnotations(t *testing.T) {
	145	+	needTools(t, "bash")
	146	+	rr, res := runResults(t, wfHead+` steps:
	147	+	- run: exit 3
	148	+	`, nil)
	149	+	if res.Conclusion != ConclusionFailure {
	150	+	t.Fatal(res)
	151	+	}
	152	+	a := rr.results[2].Annotations
	153	+	if len(a) != 1 \|\| a[0].Level != LevelFailure \|\| a[0].Message != "Process completed with exit code 3." {
	154	+	t.Errorf("%+v", a)
	155	+	}
	156	+	}
	157	+
	158	+	func TestAnnotationsAreMaskedAndOffWithoutTheFeature(t *testing.T) {
	159	+	needTools(t, "bash")
	160	+	rr, _ := runResults(t, wfHead+` steps:
	161	+	- run: \|
	162	+	echo "::add-mask::hunter2hunter2"
	163	+	echo "::warning title=hunter2hunter2::pw hunter2hunter2"
	164	+	`, nil)
	165	+	a := rr.results[2].Annotations
	166	+	if len(a) != 1 \|\| a[0].Message != "pw *" \|\| a[0].Title != "*" {
	167	+	t.Errorf("%+v", a)
	168	+	}
	169	+	rr2, _ := runResults(t, wfHead+" steps:\n - run: echo '::warning::w'\n", func(c *Config) { c.SendAnnotations = false })
	170	+	if len(rr2.results[2].Annotations) != 0 {
	171	+	t.Error("annotations without the feature")
	172	+	}
	173	+	}
	174	+
	175	+	func TestAddMaskCommand(t *testing.T) {
	176	+	needTools(t, "bash")
	177	+	rec, res := runLocal(t, wfHead+` steps:
	178	+	- name: step one
	179	+	run: \|
	180	+	echo "::add-mask::abc%0Ddef%0Aghi%0D%0Ajkl"
	181	+	echo "::add-mask:: %0D %0A %0D%0A %0D"
	182	+	echo "::add-mask::"
	183	+	echo "def ghi jkl abc"
	184	+	echo "::echo::on"
	185	+	echo "::add-mask::echoed-value"
	186	+	echo "echoed-value"
	187	+	- name: step two
	188	+	run: echo "still masked jkl"
	189	+	`, "j", nil)
	190	+	if res.Conclusion != ConclusionSuccess {
	191	+	t.Fatalf("%+v", res)
	192	+	}
	193	+	log := logOf(rec.step(t, "step one"))
	194	+	_, body, _ := strings.Cut(log, "##[endgroup]\n")
	195	+	for _, w := range []string{"* * * ", "##[warning]Can't add secret mask for empty string in ##[add-mask] command.", "::add-mask::", "\n*\n"} {
	196	+	if !strings.Contains(body+"\n", w) {
	197	+	t.Errorf("log lacks %q:\n%s", w, body)
	198	+	}
	199	+	}
	200	+	if strings.Contains(body, "echoed-value") && !strings.Contains(body, "::echo::on") {
	201	+	t.Errorf("%s", body)
	202	+	}
	203	+	if got := logOf(rec.step(t, "step two")); !strings.HasSuffix(got, "still masked ***") {
	204	+	t.Errorf("%s", got)
	205	+	}
	206	+	}
	207	+
	208	+	func TestSaveStateInRunStep(t *testing.T) {
	209	+	needTools(t, "bash")
	210	+	var j *job
	211	+	rec, res := runLocal(t, wfHead+` steps:
	212	+	- run: \|
	213	+	echo "::save-state name=Foo::bar"
	214	+	echo "baz=qux" >> "$GITHUB_STATE"
	215	+	echo "::save-state::x"
	216	+	`, "j", func(c *Config) { _ = j })
	217	+	if res.Conclusion != ConclusionFailure {
	218	+	t.Fatalf("a save-state without a name fails the step: %+v", res)
	219	+	}
	220	+	log := logOf(rec.steps[1])
	221	+	for _, w := range []string{"##[warning]The `save-state` command is deprecated", "##[error]Required field 'name' is missing in ##[save-state] command."} {
	222	+	if !strings.Contains(log, w) {
	223	+	t.Errorf("log lacks %q:\n%s", w, log)
	224	+	}
	225	+	}
	226	+	}

M internal/executor/job.go +27 -10

 	BaseEnv []string
 	// Debug turns ##[debug] lines on (ACTIONS_STEP_DEBUG).
 	Debug bool
+	// SendAnnotations and SendSummaries say that the server keeps annotations
+	// and step summaries (features ci.annotations and ci.summaries): the
+	// Reporter then gets them with StepResults.
+	SendAnnotations, SendSummaries bool
+	// Getenv reads the environment of the executor (the matcher timeout); nil
+	// means os.Getenv.
+	Getenv func(string) string
+	// StepTimeoutSkew is added to every step timeout (tests use a negative
+	// value to run a timeout of one minute in milliseconds).
+	StepTimeoutSkew time.Duration
 	Reporter Reporter
 	// Log receives the runner's own diagnostics (not the job log); the zero value
 	// masker hides the secrets in everything reported; it is set once the
 	// contexts are built, before any step runs.
 	masker atomic.Pointer[masker]
+	// Results of the commands (see issues.go, matchers.go, results.go).
+	matchers   *matcherRoot
+	issuesMu   sync.Mutex
+	collectors map[int]*issueCollector // by step number
+	outcomes   map[int]Conclusion
+	summaries  map[int]string
+	states     map[string]*intraState // intra-action state, see saveState
 }
 func (j *job) mask(s string) string { return j.masker.Load().mask(s) }
 	if cancel == nil {
 		cancel = NewCanceller()
 	}
-	j := &job{cfg: cfg, cancel: cancel, trackID: "github_" + uuid.NewString()}
+	j := &job{cfg: cfg, cancel: cancel, trackID: "github_" + uuid.NewString(), matchers: &matcherRoot{}}
 	j.cfg.Reporter = &maskReporter{j: j, next: cfg.Reporter}
 	defer func() {
 		if j.fc != nil {
 	}
 }
-// tagged writes tag+message; only the first line carries the tag.
+// tagged writes tag+message; only the first line carries the tag. The tags of
+// issues (##[error], ##[warning], ##[notice]) go through AddIssue: they are
+// logged and become annotations, like the runner's IExecutionContext.Error
+// and Warning.
 func (j *job) tagged(num int, tag, msg string) {
-	msg = j.mask(msg) // before the cut: a secret split by it would leak its start
+	if level, ok := levelOfTag(tag); ok {
-	if len(msg) > maxIssueMessageLength && tag != "" {
+		j.addIssue(num, nil, false, issue{Level: level, Message: msg})
-		msg = msg[:maxIssueMessageLength]
+		return
-	}
-	lines := strings.Split(strings.ReplaceAll(msg, "\r\n", "\n"), "\n")
-	j.write(num, tag+lines[0])
-	for _, l := range lines[1:] {
-		j.write(num, l)
 	}
+	j.logTagged(num, tag, j.mask(msg))
 }
 func (j *job) errorf(num int, format string, a ...any) {

M internal/executor/masker.go +242 -39


@@ -4,26 +4,41 @@ package executor
4			4
5		import (	5		import (
6		"encoding/base64"	6		"encoding/base64"
7	-	"encoding/json"	7	+	"sort"
8	-	"net/url"
9	-	"slices"
10		"strings"	8		"strings"
			9	+	"sync"
11		"time"	10		"time"
			11	+	"unicode/utf8"
12		)	12		)
13			13
14	-	// masker replaces secret values by *** in text that leaves the executor	14	+	// masker replaces secret values by *** in text that leaves the executor. It is
15	-	// (HostContext.SecretMasker). A value is masked as is and in the forms the	15	+	// a port of GitHub.DistributedTask.Logging.SecretMasker (Sdk/DTLogging/Logging/
16	-	// official runner registers for it (HostContext.cs:103-113, ValueEncoders): its	16	+	// SecretMasker.cs) with the value encoders HostContext registers
17	-	// base64 at the three byte offsets a prefix of one or two bytes can give	17	+	// (Runner.Common/HostContext.cs:103-113, Sdk/DTLogging/Logging/ValueEncoders.cs).
18	-	// ("user:" + secret is base64-encoded as a whole), and its JSON and URI	18	+	// A value is masked as is and in the forms the encoders give: base64 and its
19	-	// escapes. Longer forms are replaced first.	19	+	// two shifts, the command line, expression, JSON, URI, XML escapes, the value
			20	+	// without its double quotes and the sections around "&" of PowerShell.
			21	+	//
			22	+	// Values can be added while the job runs (::add-mask::). Masking finds every
			23	+	// occurrence of every value (overlaps included), merges the ranges that
			24	+	// overlap or touch and replaces each merged range by one ***, like
			25	+	// SecretMasker.MaskSecrets.
20		//	26		//
21		// Bytes that follow the secret change the last, incomplete group of its base64	27		// Bytes that follow the secret change the last, incomplete group of its base64
22		// (`echo "$T" \| base64` appends a newline), so each base64 form is also	28		// (`echo "$T" \| base64` appends a newline), so each base64 form is also
23		// registered without that group: only the characters the secret alone	29		// registered without that group: only the characters the secret alone
24	-	// determines. actions/runner (ValueEncoders.Base64StringEscapeShift) only	30	+	// determines. actions/runner only registers the full forms; the truncated ones
25	-	// registers the full forms; the truncated ones are an addition.	31	+	// are an addition of ermite.
26	-	type masker struct{ values []string }	32	+	type masker struct {
			33	+	mu sync.RWMutex
			34	+	// originals are the values passed to add (SecretMasker.m_originalValueSecrets);
			35	+	// values are the forms to look for: the originals and their encodings. A
			36	+	// value that is the encoding of an earlier one is still a new original: its
			37	+	// own encodings must be registered (AddValue tests the originals only).
			38	+	originals map[string]struct{}
			39	+	values map[string]struct{}
			40	+	list []string
			41	+	}
27			42
28		const maskedValue = "***"	43		const maskedValue = "***"
29			44

@@ -33,57 +48,243 @@ const maskedValue = "***"
33		const minBase64Tail = 8	48		const minBase64Tail = 8
34			49
35		func newMasker(secrets ...string) *masker {	50		func newMasker(secrets ...string) *masker {
36	-	seen := map[string]bool{}	51	+	m := &masker{originals: map[string]struct{}{}, values: map[string]struct{}{}}
37	-	var vals []string	52	+	for _, s := range secrets {
38	-	add := func(v string) {	53	+	m.add(s)
39	-	if v != "" && !seen[v] {	54	+	}
40	-	seen[v] = true	55	+	return m
41	-	vals = append(vals, v)	56	+	}
			57	+
			58	+	// add is SecretMasker.AddValue: the value and its encodings. An empty value is
			59	+	// ignored.
			60	+	func (m *masker) add(value string) {
			61	+	if m == nil \|\| value == "" {
			62	+	return
			63	+	}
			64	+	m.mu.RLock()
			65	+	_, known := m.originals[value]
			66	+	m.mu.RUnlock()
			67	+	if known {
			68	+	return
			69	+	}
			70	+	forms := append([]string{value}, secretEncodings(value)...)
			71	+	m.mu.Lock()
			72	+	defer m.mu.Unlock()
			73	+	m.originals[value] = struct{}{}
			74	+	for _, f := range forms {
			75	+	if f == "" {
			76	+	continue
			77	+	}
			78	+	if _, ok := m.values[f]; !ok {
			79	+	m.values[f] = struct{}{}
			80	+	m.list = append(m.list, f)
42		}	81		}
43		}	82		}
44	-	for _, s := range secrets {	83	+	}
45	-	add(s)	84	+
46	-	for _, e := range secretEncodings(s) {	85	+	// utf16Len is the length of s in .NET string units.
47	-	add(e)	86	+	func utf16Len(s string) int {
			87	+	n := 0
			88	+	for _, r := range s {
			89	+	if r >= 0x10000 {
			90	+	n += 2
			91	+	} else {
			92	+	n++
48		}	93		}
49		}	94		}
50	-	slices.SortStableFunc(vals, func(a, b string) int { return len(b) - len(a) })	95	+	return n
51	-	return &masker{values: vals}
52		}	96		}
53			97
54	-	// secretEncodings are the other forms of v that the runner masks.	98	+	// secretEncodings are the other forms of v that the runner masks, in the order
			99	+	// of HostContext.cs:103-113.
55		func secretEncodings(v string) []string {	100		func secretEncodings(v string) []string {
56		var out []string	101		var out []string
57		b := []byte(v)	102		b := []byte(v)
			103	+	// Base64StringEscape, ...Shift1, ...Shift2 (ValueEncoders.cs:17-52, 150-163).
58		for shift := range 3 {	104		for shift := range 3 {
59	-	if len(b) <= shift && shift != 0 {	105	+	sub := b
60	-	continue	106	+	if len(b) > shift {
			107	+	sub = b[shift:]
61		}	108		}
62	-	sub := b[shift:]
63		out = append(out, base64.StdEncoding.EncodeToString(sub))	109		out = append(out, base64.StdEncoding.EncodeToString(sub))
64	-	// Whole groups only: 3 bytes give 4 characters that no later byte changes.	110	+	// ermite: whole groups only, 3 bytes give 4 characters that no later
			111	+	// byte changes.
65		if n := len(sub) / 3 * 4; n >= minBase64Tail {	112		if n := len(sub) / 3 * 4; n >= minBase64Tail {
66		out = append(out, base64.StdEncoding.EncodeToString(sub[:len(sub)/3*3]))	113		out = append(out, base64.StdEncoding.EncodeToString(sub[:len(sub)/3*3]))
67		}	114		}
68		}	115		}
69	-	if j, err := json.Marshal(v); err == nil && len(j) > 2 {	116	+	out = append(out,
70	-	out = append(out, string(j[1:len(j)-1]))	117	+	strings.ReplaceAll(v, `"`, `\"`), // CommandLineArgumentEscape
71	-	}	118	+	strings.ReplaceAll(v, "'", "''"), // ExpressionStringEscape
72	-	out = append(out, url.QueryEscape(v), url.PathEscape(v))	119	+	jsonStringEscape(v),
			120	+	uriDataEscape(v),
			121	+	xmlDataEscape(v),
			122	+	trimDoubleQuotes(v),
			123	+	powerShellPreAmpersandEscape(v),
			124	+	powerShellPostAmpersandEscape(v),
			125	+	)
73		return out	126		return out
74		}	127		}
75			128
76	-	// mask returns s with every secret replaced.	129	+	// jsonStringEscape is ValueEncoders.JsonStringEscape: JsonConvert.ToString
			130	+	// without the quotes. Newtonsoft escapes the quote, the backslash, the control
			131	+	// characters below U+0020 and U+0085, U+2028, U+2029; it leaves the rest of
			132	+	// Unicode, "/" and "<>&'" alone.
			133	+	func jsonStringEscape(s string) string {
			134	+	var sb strings.Builder
			135	+	const hex = "0123456789abcdef"
			136	+	for _, r := range s {
			137	+	switch {
			138	+	case r == '"':
			139	+	sb.WriteString(`\"`)
			140	+	case r == '\\':
			141	+	sb.WriteString(`\\`)
			142	+	case r == '\t':
			143	+	sb.WriteString(`\t`)
			144	+	case r == '\n':
			145	+	sb.WriteString(`\n`)
			146	+	case r == '\r':
			147	+	sb.WriteString(`\r`)
			148	+	case r == '\b':
			149	+	sb.WriteString(`\b`)
			150	+	case r == '\f':
			151	+	sb.WriteString(`\f`)
			152	+	case r < 0x20 \|\| r == 0x85 \|\| r == 0x2028 \|\| r == 0x2029:
			153	+	sb.WriteString(`\u`)
			154	+	for shift := 12; shift >= 0; shift -= 4 {
			155	+	sb.WriteByte(hex[(r>>shift)&15])
			156	+	}
			157	+	default:
			158	+	sb.WriteRune(r)
			159	+	}
			160	+	}
			161	+	return sb.String()
			162	+	}
			163	+
			164	+	// uriDataEscape is ValueEncoders.UriDataEscape: Uri.EscapeDataString, which
			165	+	// leaves only the unreserved characters of RFC 3986 and writes the others as
			166	+	// the percent-encoded UTF-8 bytes in upper case. The runner cuts values of
			167	+	// more than 65519 characters into segments that do not split a surrogate
			168	+	// pair; the escape of a character does not depend on its neighbours, so the
			169	+	// result is the same.
			170	+	func uriDataEscape(s string) string {
			171	+	const hex = "0123456789ABCDEF"
			172	+	var sb strings.Builder
			173	+	for i := 0; i < len(s); i++ {
			174	+	c := s[i]
			175	+	if c >= 'a' && c <= 'z' \|\| c >= 'A' && c <= 'Z' \|\| c >= '0' && c <= '9' \|\| c == '-' \|\| c == '_' \|\| c == '.' \|\| c == '~' {
			176	+	sb.WriteByte(c)
			177	+	continue
			178	+	}
			179	+	sb.WriteByte('%')
			180	+	sb.WriteByte(hex[c>>4])
			181	+	sb.WriteByte(hex[c&15])
			182	+	}
			183	+	return sb.String()
			184	+	}
			185	+
			186	+	// xmlDataEscape is SecurityElement.Escape.
			187	+	func xmlDataEscape(s string) string {
			188	+	return strings.NewReplacer("<", "<", ">", ">", `"`, """, "'", "'", "&", "&").Replace(s)
			189	+	}
			190	+
			191	+	// trimDoubleQuotes is ValueEncoders.TrimDoubleQuotes: the value without its
			192	+	// quotes when it has more than 8 characters and starts and ends with one.
			193	+	func trimDoubleQuotes(s string) string {
			194	+	if utf16Len(s) > 8 && strings.HasPrefix(s, `"`) && strings.HasSuffix(s, `"`) {
			195	+	return s[1 : len(s)-1]
			196	+	}
			197	+	return ""
			198	+	}
			199	+
			200	+	// powerShellPreAmpersandEscape is ValueEncoders.PowerShellPreAmpersandEscape:
			201	+	// the part up to the last "&" (up to "&+" when there is one), when it has at
			202	+	// least 6 characters.
			203	+	func powerShellPreAmpersandEscape(s string) string {
			204	+	if !strings.Contains(s, "&") {
			205	+	return ""
			206	+	}
			207	+	var section string
			208	+	if i := strings.Index(s, "&+"); i >= 0 {
			209	+	section = s[:i+2]
			210	+	} else {
			211	+	section = s[:strings.LastIndex(s, "&")+1]
			212	+	}
			213	+	if utf16Len(section) >= 6 {
			214	+	return section
			215	+	}
			216	+	return ""
			217	+	}
			218	+
			219	+	// powerShellPostAmpersandEscape is ValueEncoders.PowerShellPostAmpersandEscape:
			220	+	// the part after the last "&" (after "&+" and the letter that got coloured),
			221	+	// when it has at least 6 characters.
			222	+	func powerShellPostAmpersandEscape(s string) string {
			223	+	if !strings.Contains(s, "&") {
			224	+	return ""
			225	+	}
			226	+	var section string
			227	+	if i := strings.Index(s, "&+"); i >= 0 {
			228	+	// Substring(i + 2 + 1): skip the letter that got coloured.
			229	+	rest := s[i+2:]
			230	+	if _, size := utf8.DecodeRuneInString(rest); size > 0 && len(rest) > size {
			231	+	section = rest[size:]
			232	+	}
			233	+	} else {
			234	+	section = s[strings.LastIndex(s, "&")+1:]
			235	+	}
			236	+	if utf16Len(section) >= 6 {
			237	+	return section
			238	+	}
			239	+	return ""
			240	+	}
			241	+
			242	+	type span struct{ start, end int }
			243	+
			244	+	// mask returns s with every secret replaced (SecretMasker.MaskSecrets).
77		func (m *masker) mask(s string) string {	245		func (m *masker) mask(s string) string {
78	-	if m == nil {	246	+	if m == nil \|\| s == "" {
			247	+	return s
			248	+	}
			249	+	var spans []span
			250	+	m.mu.RLock()
			251	+	for _, v := range m.list {
			252	+	if len(v) > len(s) \|\| !strings.Contains(s, v) {
			253	+	continue
			254	+	}
			255	+	for from := 0; from <= len(s)-len(v); {
			256	+	i := strings.Index(s[from:], v)
			257	+	if i < 0 {
			258	+	break
			259	+	}
			260	+	spans = append(spans, span{from + i, from + i + len(v)})
			261	+	from += i + 1
			262	+	}
			263	+	}
			264	+	m.mu.RUnlock()
			265	+	if len(spans) == 0 {
79		return s	266		return s
80		}	267		}
81	-	for _, v := range m.values {	268	+	sort.SliceStable(spans, func(a, b int) bool { return spans[a].start < spans[b].start })
82	-	if strings.Contains(s, v) {	269	+	var sb strings.Builder
83	-	s = strings.ReplaceAll(s, v, maskedValue)	270	+	pos := 0
			271	+	cur := spans[0]
			272	+	flush := func(sp span) {
			273	+	sb.WriteString(s[pos:sp.start])
			274	+	sb.WriteString(maskedValue)
			275	+	pos = sp.end
			276	+	}
			277	+	for _, sp := range spans[1:] {
			278	+	if sp.start <= cur.end {
			279	+	cur.end = max(cur.end, sp.end)
			280	+	continue
84		}	281		}
			282	+	flush(cur)
			283	+	cur = sp
85		}	284		}
86	-	return s	285	+	flush(cur)
			286	+	sb.WriteString(s[pos:])
			287	+	return sb.String()
87		}	288		}
88			289
89		// has reports whether s contains a secret.	290		// has reports whether s contains a secret.

@@ -106,6 +307,8 @@ func (r *maskReporter) Log(n int, at time.Time, line string) {
106		}	307		}
107			308
108		func (r *maskReporter) StepCompleted(n int, name string, c Conclusion, at time.Time) {	309		func (r *maskReporter) StepCompleted(n int, name string, c Conclusion, at time.Time) {
			310	+	// The results of the step (outcome, annotations, summary) go first.
			311	+	r.j.flushStepResults(r.next, n, c)
109		r.next.StepCompleted(n, r.j.mask(name), c, at)	312		r.next.StepCompleted(n, r.j.mask(name), c, at)
110		}	313		}
111			314

A internal/executor/masker_parity_test.go +132 -0

@@ -0,0 +1,132 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"encoding/base64"
	7	+	"strings"
	8	+	"testing"
	9	+	)
	10	+
	11	+	// Cases ported from actions/runner src/Test/L0/HostContextL0.cs
	12	+	// (DefaultSecretMaskers, SecretSectionMasking), MIT, (c) 2019 GitHub; see
	13	+	// THIRD_PARTY.md.
	14	+	func TestDefaultSecretMaskers(t *testing.T) {
	15	+	m := newMasker()
	16	+	for _, v := range []string{"Password123!", "Pass\"word\"123!", "Pass word 123!", "Pass<word>123!", "Pass'word'123!", "\"Password123!!\"", "\"short\""} {
	17	+	m.add(v)
	18	+	}
	19	+	b64 := func(s string) string { return base64.StdEncoding.EncodeToString([]byte(s)) }
	20	+	for _, tc := range []struct{ in, want string }{
	21	+	{"123Password123!123", "123***123"},
	22	+	{"password123", "password123"},
	23	+	{`123Pass\"word\"123!123`, "123***123"},
	24	+	{"123Pass%20word%20123%21123", "123***123"},
	25	+	{"123Pass<word>123!123", "123***123"},
	26	+	{"123Pass''word''123!123", "123***123"},
	27	+	{b64(":Password123!"), "OlBh***"},
	28	+	{b64("a:Password123!"), "YTpQ***"},
	29	+	{b64("ab:Password123!"), "YWI6***"},
	30	+	{b64("abc:Password123!"), "YWJjOlBh***"},
	31	+	{b64("abcd:Password123!"), "YWJjZDpQ***"},
	32	+	{b64("abcde:Password123!"), "YWJjZGU6***"},
	33	+	{"123Password123!!123", "123***123"},
	34	+	{"123short123", "123short123"},
	35	+	{"123\"short\"123", "123***123"},
	36	+	} {
	37	+	if got := m.mask(tc.in); got != tc.want {
	38	+	t.Errorf("mask(%q) = %q, want %q", tc.in, got, tc.want)
	39	+	}
	40	+	}
	41	+	}
	42	+
	43	+	func TestSecretSectionMasking(t *testing.T) {
	44	+	for _, tc := range []struct{ secret, raw, want string }{
	45	+	{"secret&secret&secret", "secret&secret&\x1b[96msecret\x1b[0m", "*\x1b[96m*\x1b[0m"},
	46	+	{"secret&secret+secret", "secret&\x1b[96msecret+secret\x1b[0m", "*\x1b[96m*\x1b[0m"},
	47	+	{"secret+secret&secret", "secret+secret&\x1b[96msecret\x1b[0m", "*\x1b[96m*\x1b[0m"},
	48	+	{"secret&secret&+secretsecret", "secret&secret&+\x1b[96ms\x1b[0mecretsecret", "*\x1b[96ms\x1b[0m*"},
	49	+	{"secret&+secret&secret", "secret&+\x1b[96ms\x1b[0mecret&secret", "*\x1b[96ms\x1b[0m*"},
	50	+	{"secret&+secret&+secret", "secret&+\x1b[96ms\x1b[0mecret&+secret", "*\x1b[96ms\x1b[0m*"},
	51	+	{"secret&+secret&secret&+secret", "secret&+\x1b[96ms\x1b[0mecret&secret&+secret", "*\x1b[96ms\x1b[0m*"},
	52	+	{"secret&secret&+", "secret&secret&+\x1b[96m\x1b[0m", "***\x1b[96m\x1b[0m"},
	53	+	} {
	54	+	m := newMasker(tc.secret)
	55	+	if got := m.mask(tc.raw); got != tc.want {
	56	+	t.Errorf("secret %q: mask(%q) = %q, want %q", tc.secret, tc.raw, got, tc.want)
	57	+	}
	58	+	}
	59	+	}
	60	+
	61	+	// Encoders of ValueEncoders.cs, one by one.
	62	+	func TestValueEncoders(t *testing.T) {
	63	+	for _, tc := range []struct{ name, got, want string }{
	64	+	{"cmdline", strings.ReplaceAll(`a"b`, `"`, `\"`), `a\"b`},
	65	+	{"json", jsonStringEscape("a\"b\\c\n\t\x01/é\u2028"), `a\"b\\c\n\t\u0001/é\u2028`},
	66	+	{"uri", uriDataEscape("a b/c~d-é"), "a%20b%2Fc~d-%C3%A9"},
	67	+	{"xml", xmlDataEscape(`<a href="x">'&'</a>`), "<a href="x">'&'</a>"},
	68	+	{"trim 9 chars", trimDoubleQuotes(`"12345678"`), "12345678"},
	69	+	{"trim 8 chars", trimDoubleQuotes(`"123456"`), ""},
	70	+	{"trim no quote", trimDoubleQuotes(`12345678901`), ""},
	71	+	{"pre", powerShellPreAmpersandEscape("secret&secret&secret"), "secret&secret&"},
	72	+	{"pre plus", powerShellPreAmpersandEscape("secret&+secret&secret"), "secret&+"},
	73	+	{"pre short", powerShellPreAmpersandEscape("ab&c"), ""},
	74	+	{"pre no ampersand", powerShellPreAmpersandEscape("secretsecret"), ""},
	75	+	{"post", powerShellPostAmpersandEscape("secret&secret&secret"), "secret"},
	76	+	{"post plus", powerShellPostAmpersandEscape("secret&+Xsecret&secret"), "secret&secret"},
	77	+	{"post plus, nothing after", powerShellPostAmpersandEscape("secret&+X"), ""},
	78	+	{"post short", powerShellPostAmpersandEscape("secret&abc"), ""},
	79	+	} {
	80	+	if tc.got != tc.want {
	81	+	t.Errorf("%s: %q, want %q", tc.name, tc.got, tc.want)
	82	+	}
	83	+	}
	84	+	}
	85	+
	86	+	// Adding a value after the first masks makes later text masked, empty values
	87	+	// are ignored, overlapping matches merge into one ***.
	88	+	func TestMaskerAddAndMerge(t *testing.T) {
	89	+	m := newMasker()
	90	+	m.add("")
	91	+	if m.mask("abc") != "abc" {
	92	+	t.Fatal("empty value masks")
	93	+	}
	94	+	m.add("abcd")
	95	+	m.add("cdef")
	96	+	if got := m.mask("xabcdefy abcd"); got != "x*y *" {
	97	+	t.Errorf("%q", got)
	98	+	}
	99	+	if got := m.mask(""); got != "" {
	100	+	t.Error(got)
	101	+	}
	102	+	// the same value again changes nothing
	103	+	m.add("abcd")
	104	+	if got := m.mask("abcd"); got != "***" {
	105	+	t.Error(got)
	106	+	}
	107	+	}
	108	+
	109	+	// SecretMasker.AddValue skips a value only when it was added before as an
	110	+	// original, not when it is already one of the forms of another value: the
	111	+	// encodings of "one%20two" are masked after "one two" was added, although
	112	+	// "one%20two" itself is the URI form of "one two" (GO-001).
	113	+	func TestMaskerAddsEncodingsOfAValueThatIsAnEncodingOfAnother(t *testing.T) {
	114	+	m := newMasker()
	115	+	m.add("one two")
	116	+	m.add("one%20two")
	117	+	for _, text := range []string{"one two", "one%20two", "one%2520two"} {
	118	+	if got := m.mask(text); got != "***" {
	119	+	t.Errorf("mask(%q) = %q", text, got)
	120	+	}
	121	+	}
	122	+	// the same original twice is still a no-op
	123	+	m.add("one%20two")
	124	+	if n := len(m.list); n == 0 {
	125	+	t.Fatal("empty")
	126	+	}
	127	+	before := len(m.list)
	128	+	m.add("one%20two")
	129	+	if len(m.list) != before {
	130	+	t.Error("an original added twice grew the list")
	131	+	}
	132	+	}

M internal/executor/masker_test.go +1 -1


@@ -49,7 +49,7 @@ func TestMaskerForms(t *testing.T) {
49		}	49		}
50		// special characters: the JSON and URL forms	50		// special characters: the JSON and URL forms
51		s := newMasker(`a"b/c d`)	51		s := newMasker(`a"b/c d`)
52	-	for _, text := range []string{`a"b/c d`, `a\"b/c d`, `a%22b%2Fc+d`, `a%22b%2Fc%20d`} {	52	+	for _, text := range []string{`a"b/c d`, `a\"b/c d`, `a%22b%2Fc%20d`} {
53		if got := s.mask(text); strings.Contains(got, "b") {	53		if got := s.mask(text); strings.Contains(got, "b") {
54		t.Errorf("%q -> %q", text, got)	54		t.Errorf("%q -> %q", text, got)
55		}	55		}

A internal/executor/matchers.go +412 -0

@@ -0,0 +1,412 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"encoding/json"
	7	+	"fmt"
	8	+	"strings"
	9	+	"sync"
	10	+	"time"
	11	+
	12	+	"github.com/dlclark/regexp2"
	13	+	)
	14	+
	15	+	// Problem matchers: a port of Runner.Worker/IssueMatcher.cs (actions/runner,
	16	+	// MIT). The regular expressions are .NET's with RegexOptions.CultureInvariant \|
	17	+	// RegexOptions.ECMAScript (IssueMatcher.cs:450); regexp2 is the .NET engine in
	18	+	// Go (RE2 has no lookarounds or backreferences, which real matchers use).
	19	+
	20	+	// optInt is an int? of the JSON files: a number, a numeric string or null.
	21	+	type optInt struct {
	22	+	set bool
	23	+	v int
	24	+	}
	25	+
	26	+	func (o *optInt) UnmarshalJSON(b []byte) error {
	27	+	s := strings.TrimSpace(string(b))
	28	+	if s == "null" {
	29	+	return nil
	30	+	}
	31	+	s = strings.Trim(s, `"`)
	32	+	var n int
	33	+	if _, err := fmt.Sscanf(s, "%d", &n); err != nil {
	34	+	return ghErrorf("Error converting value %s to type 'System.Nullable`1[System.Int32]'.", string(b))
	35	+	}
	36	+	o.set, o.v = true, n
	37	+	return nil
	38	+	}
	39	+
	40	+	// optBool is a bool of the JSON files: a boolean or the string "true"/"false".
	41	+	type optBool bool
	42	+
	43	+	func (o *optBool) UnmarshalJSON(b []byte) error {
	44	+	switch strings.ToLower(strings.Trim(strings.TrimSpace(string(b)), `"`)) {
	45	+	case "true":
	46	+	*o = true
	47	+	case "false", "null":
	48	+	*o = false
	49	+	default:
	50	+	return ghErrorf("Error converting value %s to type 'System.Boolean'.", string(b))
	51	+	}
	52	+	return nil
	53	+	}
	54	+
	55	+	// patternConfig is IssuePatternConfig.
	56	+	type patternConfig struct {
	57	+	File optInt `json:"file"`
	58	+	Line optInt `json:"line"`
	59	+	Column optInt `json:"column"`
	60	+	Severity optInt `json:"severity"`
	61	+	Code optInt `json:"code"`
	62	+	Message optInt `json:"message"`
	63	+	FromPath optInt `json:"fromPath"`
	64	+	Loop optBool `json:"loop"`
	65	+	Regexp string `json:"regexp"`
	66	+	}
	67	+
	68	+	// matcherConfig is IssueMatcherConfig.
	69	+	type matcherConfig struct {
	70	+	Owner string `json:"owner"`
	71	+	Severity string `json:"severity"`
	72	+	Patterns []patternConfig `json:"pattern"`
	73	+	FromPath string `json:"fromPath"`
	74	+	}
	75	+
	76	+	// matchersConfig is IssueMatchersConfig.
	77	+	type matchersConfig struct {
	78	+	Matchers []*matcherConfig `json:"problemMatcher"`
	79	+	}
	80	+
	81	+	// parseMatchersConfig reads the JSON of a matchers file.
	82	+	func parseMatchersConfig(data []byte) (*matchersConfig, error) {
	83	+	data = []byte(strings.TrimPrefix(string(data), "\xef\xbb\xbf"))
	84	+	var c matchersConfig
	85	+	if len(strings.TrimSpace(string(data))) == 0 {
	86	+	return nil, nil // StringUtil.ConvertFromJson of an empty text is null
	87	+	}
	88	+	if err := json.Unmarshal(data, &c); err != nil {
	89	+	return nil, err
	90	+	}
	91	+	return &c, nil
	92	+	}
	93	+
	94	+	// regexOptions is IssuePatternConfig.RegexOptions. regexp2 has no
	95	+	// CultureInvariant: its matching is culture independent.
	96	+	const regexOptions = regexp2.ECMAScript
	97	+
	98	+	func compilePattern(p string) (*regexp2.Regexp, error) {
	99	+	return regexp2.Compile(p, regexOptions)
	100	+	}
	101	+
	102	+	// validate is IssueMatchersConfig.Validate (IssueMatcher.cs:262). The error
	103	+	// texts are the runner's.
	104	+	func (c *matchersConfig) validate() error {
	105	+	owners := map[string]bool{}
	106	+	for _, m := range c.Matchers {
	107	+	if m == nil {
	108	+	m = &matcherConfig{}
	109	+	}
	110	+	if err := m.validate(); err != nil {
	111	+	return err
	112	+	}
	113	+	lo := strings.ToLower(m.Owner)
	114	+	if owners[lo] {
	115	+	return ghErrorf("Duplicate owner name '%s'", m.Owner)
	116	+	}
	117	+	owners[lo] = true
	118	+	}
	119	+	return nil
	120	+	}
	121	+
	122	+	// validate is IssueMatcherConfig.Validate (IssueMatcher.cs:376).
	123	+	func (m *matcherConfig) validate() error {
	124	+	if m.Owner == "" {
	125	+	return ghErrorf("Owner must not be empty")
	126	+	}
	127	+	switch strings.ToUpper(m.Severity) {
	128	+	case "", "ERROR", "WARNING", "NOTICE":
	129	+	default:
	130	+	return ghErrorf("Matcher '%s' contains unexpected default severity '%s'", m.Owner, m.Severity)
	131	+	}
	132	+	if len(m.Patterns) == 0 {
	133	+	return ghErrorf("Matcher '%s' does not contain any patterns", m.Owner)
	134	+	}
	135	+	var file, line, column, severity, code, message, fromPath *int
	136	+	for i := range m.Patterns {
	137	+	isFirst, isLast := i == 0, i == len(m.Patterns)-1
	138	+	if err := m.Patterns[i].validate(isFirst, isLast, &file, &line, &column, &severity, &code, &message, &fromPath); err != nil {
	139	+	return err
	140	+	}
	141	+	}
	142	+	if message == nil {
	143	+	return ghErrorf("At least one pattern must set 'message'")
	144	+	}
	145	+	return nil
	146	+	}
	147	+
	148	+	// validate is IssuePatternConfig.Validate (IssueMatcher.cs:495).
	149	+	func (p patternConfig) validate(isFirst, isLast bool, file, line, column, severity, code, message, fromPath *int) error {
	150	+	if bool(p.Loop) && (isFirst \|\| !isLast) {
	151	+	return ghErrorf("Only the last pattern in a multiline matcher may set 'loop'")
	152	+	}
	153	+	if bool(p.Loop) && !p.Message.set {
	154	+	return ghErrorf("The loop pattern must set 'message'")
	155	+	}
	156	+	re, err := compilePattern(p.Regexp)
	157	+	if err != nil {
	158	+	return err
	159	+	}
	160	+	groupCount := len(re.GetGroupNumbers())
	161	+	for _, f := range []struct {
	162	+	name string
	163	+	v optInt
	164	+	to **int
	165	+	}{
	166	+	{"file", p.File, file}, {"line", p.Line, line}, {"column", p.Column, column},
	167	+	{"severity", p.Severity, severity}, {"code", p.Code, code}, {"message", p.Message, message},
	168	+	{"fromPath", p.FromPath, fromPath},
	169	+	} {
	170	+	if !f.v.set {
	171	+	continue
	172	+	}
	173	+	if *f.to != nil {
	174	+	return ghErrorf("The property '%s' is set twice", f.name)
	175	+	}
	176	+	if f.v.v < 0 \|\| f.v.v >= groupCount {
	177	+	return ghErrorf("The property '%s' is set to %d which is out of range", f.name, f.v.v)
	178	+	}
	179	+	n := f.v.v
	180	+	*f.to = &n
	181	+	}
	182	+	return nil
	183	+	}
	184	+
	185	+	// errMatchTimeout is the RegexMatchTimeoutException; its message is .NET's.
	186	+	var errMatchTimeout = msgError("The Regex engine has timed out while trying to match a pattern to an input string. This can occur for many reasons, including very large inputs or excessive backtracking caused by nested quantifiers, back-references and other factors.")
	187	+
	188	+	// issuePattern is IssuePattern.
	189	+	type issuePattern struct {
	190	+	file, line, column, severity, code, message, fromPath optInt
	191	+	loop bool
	192	+	re *regexp2.Regexp
	193	+	}
	194	+
	195	+	// nstr is a string that can be null, as the values of IssueMatch are: a group
	196	+	// that the pattern does not name is null, a group that matched nothing is "".
	197	+	type nstr struct {
	198	+	s string
	199	+	ok bool
	200	+	}
	201	+
	202	+	func (n nstr) or(o nstr) nstr {
	203	+	if n.ok {
	204	+	return n
	205	+	}
	206	+	return o
	207	+	}
	208	+
	209	+	// issueMatch is IssueMatch.
	210	+	type issueMatch struct {
	211	+	file, line, column, severity, code, message, fromPath nstr
	212	+	}
	213	+
	214	+	// issueMatcher is IssueMatcher: a matcher config with the state of the
	215	+	// multi-line patterns.
	216	+	type issueMatcher struct {
	217	+	owner, defaultSeverity, defaultFromPath string
	218	+	patterns []*issuePattern
	219	+	state []*issueMatch
	220	+	}
	221	+
	222	+	func newIssueMatcher(c matcherConfig, timeout time.Duration) (issueMatcher, error) {
	223	+	m := &issueMatcher{owner: c.Owner, defaultSeverity: c.Severity, defaultFromPath: c.FromPath}
	224	+	for _, pc := range c.Patterns {
	225	+	re, err := compilePattern(pc.Regexp)
	226	+	if err != nil {
	227	+	return nil, err
	228	+	}
	229	+	re.MatchTimeout = timeout
	230	+	m.patterns = append(m.patterns, &issuePattern{
	231	+	file: pc.File, line: pc.Line, column: pc.Column, severity: pc.Severity, code: pc.Code,
	232	+	message: pc.Message, fromPath: pc.FromPath, loop: bool(pc.Loop), re: re,
	233	+	})
	234	+	}
	235	+	m.reset()
	236	+	return m, nil
	237	+	}
	238	+
	239	+	func (m issueMatcher) reset() { m.state = make([]issueMatch, max(len(m.patterns)-1, 0)) }
	240	+
	241	+	// groupValue is IssueMatch.GetValue: the text of a group, null when the
	242	+	// pattern does not name one or its number is out of range.
	243	+	func groupValue(match *regexp2.Match, idx optInt) nstr {
	244	+	if !idx.set \|\| idx.v >= match.GroupCount() {
	245	+	return nstr{}
	246	+	}
	247	+	g := match.GroupByNumber(idx.v)
	248	+	if g == nil {
	249	+	return nstr{}
	250	+	}
	251	+	return nstr{g.String(), true}
	252	+	}
	253	+
	254	+	func newIssueMatch(running issueMatch, p issuePattern, g regexp2.Match, defSeverity, defFromPath string) issueMatch {
	255	+	r := running
	256	+	if r == nil {
	257	+	r = &issueMatch{}
	258	+	}
	259	+	im := &issueMatch{
	260	+	file: r.file.or(groupValue(g, p.file)),
	261	+	line: r.line.or(groupValue(g, p.line)),
	262	+	column: r.column.or(groupValue(g, p.column)),
	263	+	severity: r.severity.or(groupValue(g, p.severity)),
	264	+	code: r.code.or(groupValue(g, p.code)),
	265	+	message: r.message.or(groupValue(g, p.message)),
	266	+	fromPath: r.fromPath.or(groupValue(g, p.fromPath)),
	267	+	}
	268	+	if im.severity.s == "" && defSeverity != "" {
	269	+	im.severity = nstr{defSeverity, true}
	270	+	}
	271	+	if im.fromPath.s == "" && defFromPath != "" {
	272	+	im.fromPath = nstr{defFromPath, true}
	273	+	}
	274	+	return im
	275	+	}
	276	+
	277	+	// match is IssueMatcher.Match. A timeout of the engine is returned as
	278	+	// errMatchTimeout.
	279	+	func (m issueMatcher) match(line string) (issueMatch, error) {
	280	+	find := func(p issuePattern) (regexp2.Match, error) {
	281	+	mt, err := p.re.FindStringMatch(line)
	282	+	if err != nil {
	283	+	return nil, errMatchTimeout
	284	+	}
	285	+	return mt, nil
	286	+	}
	287	+	if len(m.patterns) == 1 {
	288	+	p := m.patterns[0]
	289	+	mt, err := find(p)
	290	+	if err != nil \|\| mt == nil {
	291	+	return nil, err
	292	+	}
	293	+	return newIssueMatch(nil, p, mt, m.defaultSeverity, m.defaultFromPath), nil
	294	+	}
	295	+	for i := len(m.patterns) - 1; i >= 0; i-- {
	296	+	var running *issueMatch
	297	+	if i > 0 {
	298	+	running = m.state[i-1]
	299	+	}
	300	+	if i != 0 && running == nil {
	301	+	continue
	302	+	}
	303	+	p := m.patterns[i]
	304	+	isLast := i == len(m.patterns)-1
	305	+	mt, err := find(p)
	306	+	if err != nil {
	307	+	return nil, err
	308	+	}
	309	+	if mt != nil {
	310	+	if isLast {
	311	+	if p.loop {
	312	+	m.reset()
	313	+	m.state[i-1] = running
	314	+	} else {
	315	+	m.reset()
	316	+	}
	317	+	return newIssueMatch(running, p, mt, m.defaultSeverity, m.defaultFromPath), nil
	318	+	}
	319	+	m.state[i] = newIssueMatch(running, p, mt, "", "")
	320	+	} else if isLast {
	321	+	m.state[i-1] = nil
	322	+	} else {
	323	+	m.state[i] = nil
	324	+	}
	325	+	}
	326	+	return nil, nil
	327	+	}
	328	+
	329	+	// matcherRoot holds the matchers of the job (ExecutionContext._matchers, on the
	330	+	// root context) and tells the output managers of the steps that run when they
	331	+	// change (OnMatcherChanged).
	332	+	type matcherRoot struct {
	333	+	mu sync.Mutex
	334	+	configs []*matcherConfig
	335	+	handlers map[*outputManager]struct{}
	336	+	}
	337	+
	338	+	// snapshot returns the matchers now.
	339	+	func (r matcherRoot) snapshot() []matcherConfig {
	340	+	r.mu.Lock()
	341	+	defer r.mu.Unlock()
	342	+	return append([]*matcherConfig(nil), r.configs...)
	343	+	}
	344	+
	345	+	func (r matcherRoot) subscribe(o outputManager) {
	346	+	r.mu.Lock()
	347	+	defer r.mu.Unlock()
	348	+	if r.handlers == nil {
	349	+	r.handlers = map[*outputManager]struct{}{}
	350	+	}
	351	+	r.handlers[o] = struct{}{}
	352	+	}
	353	+
	354	+	func (r matcherRoot) unsubscribe(o outputManager) {
	355	+	r.mu.Lock()
	356	+	defer r.mu.Unlock()
	357	+	delete(r.handlers, o)
	358	+	}
	359	+
	360	+	// add is ExecutionContext.AddMatchers (:1173): the new matchers go first, those
	361	+	// of the same owner (ignoring case) are replaced. It returns the debug line.
	362	+	func (r matcherRoot) add(c matchersConfig) string {
	363	+	r.mu.Lock()
	364	+	defer r.mu.Unlock()
	365	+	owners := map[string]bool{}
	366	+	var next []*matcherConfig
	367	+	for _, m := range c.Matchers {
	368	+	owners[strings.ToLower(m.Owner)] = true
	369	+	next = append(next, m)
	370	+	}
	371	+	for _, m := range r.configs {
	372	+	if !owners[strings.ToLower(m.Owner)] {
	373	+	next = append(next, m)
	374	+	}
	375	+	}
	376	+	r.configs = next
	377	+	var names []string
	378	+	for _, m := range c.Matchers {
	379	+	names = append(names, "'"+m.Owner+"'")
	380	+	for o := range r.handlers {
	381	+	o.matcherChanged(m)
	382	+	}
	383	+	}
	384	+	return "Added matchers: " + strings.Join(names, ", ") + ". Problem matchers scan action output for known warning or error strings and report these inline."
	385	+	}
	386	+
	387	+	// remove is ExecutionContext.RemoveMatchers (:1212). It returns the debug line.
	388	+	func (r *matcherRoot) remove(owners []string) string {
	389	+	r.mu.Lock()
	390	+	defer r.mu.Unlock()
	391	+	distinct := map[string]bool{}
	392	+	for _, o := range owners {
	393	+	distinct[strings.ToLower(o)] = true
	394	+	}
	395	+	var kept, removed []*matcherConfig
	396	+	for _, m := range r.configs {
	397	+	if distinct[strings.ToLower(m.Owner)] {
	398	+	removed = append(removed, m)
	399	+	} else {
	400	+	kept = append(kept, m)
	401	+	}
	402	+	}
	403	+	r.configs = kept
	404	+	var names []string
	405	+	for _, m := range removed {
	406	+	names = append(names, "'"+m.Owner+"'")
	407	+	for o := range r.handlers {
	408	+	o.matcherChanged(&matcherConfig{Owner: m.Owner})
	409	+	}
	410	+	}
	411	+	return "Removed matchers: " + strings.Join(names, ", ")
	412	+	}

A internal/executor/matchers_test.go +195 -0

@@ -0,0 +1,195 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"strings"
	7	+	"testing"
	8	+	"time"
	9	+	)
	10	+
	11	+	func mustConfig(t testing.T, js string) matchersConfig {
	12	+	t.Helper()
	13	+	c, err := parseMatchersConfig([]byte(js))
	14	+	if err != nil \|\| c == nil {
	15	+	t.Fatalf("parse: %v", err)
	16	+	}
	17	+	return c
	18	+	}
	19	+
	20	+	// Cases of actions/runner src/Test/L0/Worker/IssueMatcherL0.cs (MIT, (c) 2019
	21	+	// GitHub; see THIRD_PARTY.md): Config_Validate_*.
	22	+	func TestMatcherConfigValidate(t *testing.T) {
	23	+	one := func(extra string) string {
	24	+	return `{"problemMatcher":[{"owner":"myMatcher","pattern":[` + extra + `]}]}`
	25	+	}
	26	+	for _, tc := range []struct{ name, js, err string }{
	27	+	{"loop on a single pattern", one(`{"regexp":"^error: (.+)$","message":1,"loop":true}`), "Only the last pattern in a multiline matcher may set 'loop'"},
	28	+	{"loop sanity", one(`{"regexp":"^file: (.+)$","file":1},{"regexp":"^error: (.+)$","message":1,"loop":true}`), ""},
	29	+	{"loop only on the last", one(`{"regexp":"^(error)$","severity":1},{"regexp":"^file: (.+)$","file":1,"loop":true},{"regexp":"^error: (.+)$","message":1}`), "Only the last pattern in a multiline matcher may set 'loop'"},
	30	+	{"loop must set message", one(`{"regexp":"^file: (.+)$","message":1},{"regexp":"^file: (.+)$","file":1,"loop":true}`), "The loop pattern must set 'message'"},
	31	+	{"message in the first pattern", one(`{"regexp":"^file: (.+)$","message":1},{"regexp":"^error: (.+)$","file":1}`), ""},
	32	+	{"message required", one(`{"regexp":"^error: (.+)$","file":1}`), "At least one pattern must set 'message'"},
	33	+	{"owners distinct", `{"problemMatcher":[{"owner":"myMatcher","pattern":[{"regexp":"^error: (.+)$","message":1}]},{"owner":"MYmatcher","pattern":[{"regexp":"^ERR: (.+)$","message":1}]}]}`, "Duplicate owner name 'MYmatcher'"},
	34	+	{"owner required", `{"problemMatcher":[{"pattern":[{"regexp":"^(.+)$","message":1}]}]}`, "Owner must not be empty"},
	35	+	{"pattern required", `{"problemMatcher":[{"owner":"m"}]}`, "Matcher 'm' does not contain any patterns"},
	36	+	{"property set twice", one(`{"regexp":"^(.+) (.+)$","file":1,"message":2},{"regexp":"^(.+)$","file":1}`), "The property 'file' is set twice"},
	37	+	{"out of range", one(`{"regexp":"^(.+)$","message":2}`), "The property 'message' is set to 2 which is out of range"},
	38	+	{"less than zero", one(`{"regexp":"^(.+)$","message":-1}`), "The property 'message' is set to -1 which is out of range"},
	39	+	{"bad severity", `{"problemMatcher":[{"owner":"m","severity":"fatal","pattern":[{"regexp":"(.+)","message":1}]}]}`, "Matcher 'm' contains unexpected default severity 'fatal'"},
	40	+	} {
	41	+	err := mustConfig(t, tc.js).validate()
	42	+	switch {
	43	+	case tc.err == "" && err != nil:
	44	+	t.Errorf("%s: %v", tc.name, err)
	45	+	case tc.err != "" && (err == nil \|\| err.Error() != tc.err):
	46	+	t.Errorf("%s: %v, want %q", tc.name, err, tc.err)
	47	+	}
	48	+	}
	49	+	}
	50	+
	51	+	func newMatcher(t testing.T, js string) issueMatcher {
	52	+	t.Helper()
	53	+	c := mustConfig(t, js)
	54	+	if err := c.validate(); err != nil {
	55	+	t.Fatal(err)
	56	+	}
	57	+	m, err := newIssueMatcher(c.Matchers[0], time.Second)
	58	+	if err != nil {
	59	+	t.Fatal(err)
	60	+	}
	61	+	return m
	62	+	}
	63	+
	64	+	func matchOf(t testing.T, m issueMatcher, line string) *issueMatch {
	65	+	t.Helper()
	66	+	r, err := m.match(line)
	67	+	if err != nil {
	68	+	t.Fatal(err)
	69	+	}
	70	+	return r
	71	+	}
	72	+
	73	+	// IssueMatcherL0.Matcher_MultiplePatterns_Loop_AccumulatesStatePerLine.
	74	+	func TestMatcherLoopAccumulatesState(t *testing.T) {
	75	+	m := newMatcher(t, `{"problemMatcher":[{"owner":"myMatcher","pattern":[
	76	+	{"regexp":"^(.+)$","file":1},{"regexp":"^(.+)$","code":1},{"regexp":"^message:(.+)$","message":1,"loop":true}]}]}`)
	77	+	type want struct{ file, code, msg string }
	78	+	check := func(line string, w *want) {
	79	+	t.Helper()
	80	+	got := matchOf(t, m, line)
	81	+	switch {
	82	+	case w == nil && got != nil:
	83	+	t.Fatalf("%q: matched %+v", line, got)
	84	+	case w != nil && (got == nil \|\| got.file.s != w.file \|\| got.code.s != w.code \|\| got.message.s != w.msg):
	85	+	t.Fatalf("%q: %+v, want %+v", line, got, w)
	86	+	}
	87	+	}
	88	+	check("file1", nil)
	89	+	check("code1", nil)
	90	+	check("message:message1", &want{"file1", "code1", "message1"})
	91	+	check("message:message1-2", &want{"file1", "code1", "message1-2"}) // the loop keeps the running match
	92	+	check("abc", nil) // discarded
	93	+	check("file2", nil)
	94	+	check("code2", nil)
	95	+	check("message:message2", &want{"file2", "code2", "message2"})
	96	+	check("abc", nil)
	97	+	check("abc", nil)
	98	+	check("file3", nil)
	99	+	check("code3", nil)
	100	+	check("message:message3", &want{"file3", "code3", "message3"})
	101	+	}
	102	+
	103	+	// IssueMatcherL0.Matcher_MultiplePatterns_NonLoop_*: no loop, a match clears
	104	+	// the state.
	105	+	func TestMatcherNonLoop(t *testing.T) {
	106	+	m := newMatcher(t, `{"problemMatcher":[{"owner":"m","pattern":[
	107	+	{"regexp":"^(.+)$","file":1},{"regexp":"^message:(.+)$","message":1}]}]}`)
	108	+	if matchOf(t, m, "file1") != nil {
	109	+	t.Fatal("early match")
	110	+	}
	111	+	if got := matchOf(t, m, "message:m1"); got == nil \|\| got.file.s != "file1" \|\| got.message.s != "m1" {
	112	+	t.Fatalf("%+v", got)
	113	+	}
	114	+	// "message:m2" is also a file line (first pattern matches every line).
	115	+	if got := matchOf(t, m, "message:m2"); got != nil {
	116	+	t.Fatalf("a non loop pattern matched without a running match: %+v", got)
	117	+	}
	118	+	}
	119	+
	120	+	// IssueMatcherL0.Matcher_SinglePattern_ExtractsProperties, DefaultSeverity,
	121	+	// DefaultFromPath.
	122	+	func TestMatcherSinglePattern(t *testing.T) {
	123	+	m := newMatcher(t, `{"problemMatcher":[{"owner":"m","severity":"warning","fromPath":"web/package.json","pattern":[
	124	+	{"regexp":"^(.+):(\\d+):(\\d+) (\\w+)? (\\w+) (.+)$","file":1,"line":2,"column":3,"severity":4,"code":5,"message":6}]}]}`)
	125	+	got := matchOf(t, m, "file.js:5:10 error E1 something bad")
	126	+	if got == nil \|\| got.file.s != "file.js" \|\| got.line.s != "5" \|\| got.column.s != "10" \|\| got.severity.s != "error" \|\| got.code.s != "E1" \|\| got.message.s != "something bad" \|\| got.fromPath.s != "web/package.json" {
	127	+	t.Fatalf("%+v", got)
	128	+	}
	129	+	// A group that took no part gives "" and the default severity applies.
	130	+	got = matchOf(t, m, "file.js:5:10 E1 msg")
	131	+	if got == nil \|\| got.severity.s != "warning" {
	132	+	t.Fatalf("%+v", got)
	133	+	}
	134	+	if matchOf(t, m, "nothing") != nil {
	135	+	t.Fatal("matched")
	136	+	}
	137	+	}
	138	+
	139	+	// ECMAScript semantics (\d is ASCII only) and lookarounds, which RE2 lacks.
	140	+	func TestMatcherRegexFlavour(t *testing.T) {
	141	+	m := newMatcher(t, `{"problemMatcher":[{"owner":"m","pattern":[{"regexp":"^(?<=ERR )(\\d+) (?!ignored)(.+)$","line":1,"message":2}]}]}`)
	142	+	_ = m
	143	+	m = newMatcher(t, `{"problemMatcher":[{"owner":"m","pattern":[{"regexp":"^(\\d+) (.+)$","line":1,"message":2}]}]}`)
	144	+	if matchOf(t, m, "١٢ arabic digits") != nil {
	145	+	t.Error("\\d must be ASCII with RegexOptions.ECMAScript")
	146	+	}
	147	+	if matchOf(t, m, "12 ascii") == nil {
	148	+	t.Error("ASCII digits")
	149	+	}
	150	+	b := newMatcher(t, `{"problemMatcher":[{"owner":"m","pattern":[{"regexp":"^(a)\\1 (.+)$","message":2}]}]}`)
	151	+	if matchOf(t, b, "aa backreference") == nil {
	152	+	t.Error("backreference")
	153	+	}
	154	+	}
	155	+
	156	+	// AC6b: a catastrophic pattern times out in about a second and does not stall
	157	+	// the step.
	158	+	func TestMatcherCatastrophicPatternTimesOut(t *testing.T) {
	159	+	m := newMatcher(t, `{"problemMatcher":[{"owner":"bad","pattern":[{"regexp":"^(a+)+$","message":1}]}]}`)
	160	+	start := time.Now()
	161	+	_, err := m.match(strings.Repeat("a", 30) + "!")
	162	+	took := time.Since(start)
	163	+	if err == nil \|\| !strings.HasPrefix(err.Error(), "The Regex engine has timed out while trying to match a pattern to an input string.") {
	164	+	t.Fatalf("err %v after %v", err, took)
	165	+	}
	166	+	if took < 900time.Millisecond \|\| took > 3time.Second {
	167	+	t.Errorf("timed out after %v, want about 1 s", took)
	168	+	}
	169	+	}
	170	+
	171	+	func TestParseTimeSpan(t *testing.T) {
	172	+	for in, want := range map[string]time.Duration{
	173	+	"0:0:0.01": 10 * time.Millisecond, "00:00:05": 5 * time.Second, "0:2": 2 * time.Minute, "1.02:03:04": 26time.Hour + 3time.Minute + 4*time.Second,
	174	+	"1": 24 * time.Hour,
	175	+	} {
	176	+	if got, ok := parseTimeSpan(in); !ok \|\| got != want {
	177	+	t.Errorf("%q: %v %v, want %v", in, got, ok, want)
	178	+	}
	179	+	}
	180	+	for _, in := range []string{"", "abc", "1:2:3:4", "25:00:00", "0:61"} {
	181	+	if _, ok := parseTimeSpan(in); ok {
	182	+	t.Errorf("%q parsed", in)
	183	+	}
	184	+	}
	185	+	env := func(m map[string]string) func(string) string { return func(k string) string { return m[k] } }
	186	+	if d := matcherTimeout(env(nil)); d != time.Second {
	187	+	t.Error(d)
	188	+	}
	189	+	if d := matcherTimeout(env(map[string]string{matcherTimeoutKey: "00:00:05"})); d != 5*time.Second {
	190	+	t.Error(d)
	191	+	}
	192	+	if d := matcherTimeout(env(map[string]string{matcherTimeoutKey: "-1"})); d != time.Second {
	193	+	t.Error(d)
	194	+	}
	195	+	}

A internal/executor/outputmgr.go +411 -0

@@ -0,0 +1,411 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"fmt"
	7	+	"os"
	8	+	"path/filepath"
	9	+	"strconv"
	10	+	"strings"
	11	+	"sync"
	12	+	"time"
	13	+	"unicode"
	14	+
	15	+	"github.com/dlclark/regexp2"
	16	+	)
	17	+
	18	+	// outputManager is OutputManager (Runner.Worker/Handlers/OutputManager.cs): it
	19	+	// receives the lines a step prints, runs the workflow commands and the
	20	+	// problem matchers on them, and logs what is left. One per process of a step.
	21	+
	22	+	const (
	23	+	// maxMatcherAttempts is OutputManager._maxAttempts.
	24	+	maxMatcherAttempts = 3
	25	+	// matcherTimeoutKey is OutputManager._timeoutKey.
	26	+	matcherTimeoutKey = "GITHUB_ACTIONS_RUNNER_ISSUE_MATCHER_TIMEOUT"
	27	+	// repoPathFailsafe is OutputManager._failsafe.
	28	+	repoPathFailsafe = 50
	29	+	)
	30	+
	31	+	// colorCodeRegex is OutputManager._colorCodeRegex, @"\x0033\[[0-9;]*m?". In
	32	+	// .NET "\x00" takes exactly two hex digits, so the pattern is NUL, "33", "["
	33	+	// and not ESC: the runner strips nothing from real terminal colors (its own
	34	+	// test writes "\033", which C# reads as NUL followed by "33"). Ported as is.
	35	+	var colorCodeRegex = regexp2.MustCompile("\x0033\\[[0-9;]*m?", 0)
	36	+
	37	+	// colorCodePrefix is OutputManager._colorCodePrefix, "\033[": NUL, "33[".
	38	+	const colorCodePrefix = "\x0033["
	39	+
	40	+	// parseTimeSpan is TimeSpan.TryParse with the invariant culture: "d" days,
	41	+	// "hh:mm", "hh:mm:ss[.fffffff]" and "d.hh:mm:ss[.fffffff]", with an optional
	42	+	// leading minus.
	43	+	func parseTimeSpan(s string) (time.Duration, bool) {
	44	+	s = strings.TrimSpace(s)
	45	+	if s == "" {
	46	+	return 0, false
	47	+	}
	48	+	neg := strings.HasPrefix(s, "-")
	49	+	s = strings.TrimPrefix(s, "-")
	50	+	var days int64
	51	+	parts := strings.Split(s, ":")
	52	+	if len(parts) == 1 {
	53	+	n, err := strconv.ParseInt(s, 10, 32)
	54	+	if err != nil {
	55	+	return 0, false
	56	+	}
	57	+	d := time.Duration(n) * 24 * time.Hour
	58	+	if neg {
	59	+	d = -d
	60	+	}
	61	+	return d, true
	62	+	}
	63	+	if len(parts) > 3 {
	64	+	return 0, false
	65	+	}
	66	+	if d, rest, ok := strings.Cut(parts[0], "."); ok {
	67	+	n, err := strconv.ParseInt(d, 10, 32)
	68	+	if err != nil {
	69	+	return 0, false
	70	+	}
	71	+	days, parts[0] = n, rest
	72	+	}
	73	+	num := func(x string) (int64, bool) {
	74	+	n, err := strconv.ParseInt(x, 10, 32)
	75	+	return n, err == nil && n >= 0
	76	+	}
	77	+	h, ok := num(parts[0])
	78	+	if !ok {
	79	+	return 0, false
	80	+	}
	81	+	m, ok := num(parts[1])
	82	+	if !ok \|\| m > 59 {
	83	+	return 0, false
	84	+	}
	85	+	var sec float64
	86	+	if len(parts) == 3 {
	87	+	f, err := strconv.ParseFloat(parts[2], 64)
	88	+	if err != nil \|\| f < 0 \|\| f >= 60 \|\| strings.ContainsAny(parts[2], "eE+-") {
	89	+	return 0, false
	90	+	}
	91	+	sec = f
	92	+	}
	93	+	if h > 23 {
	94	+	return 0, false
	95	+	}
	96	+	d := time.Duration(days)24time.Hour + time.Duration(h)time.Hour + time.Duration(m)time.Minute + time.Duration(sec*float64(time.Second))
	97	+	if neg {
	98	+	d = -d
	99	+	}
	100	+	return d, true
	101	+	}
	102	+
	103	+	// matcherTimeout is the constructor of OutputManager (:43-60): the variable of
	104	+	// the job, then the environment of the runner, then one second. ermite has no
	105	+	// job variables; the environment is the executor's own, as the runner's is its
	106	+	// worker's.
	107	+	func matcherTimeout(getenv func(string) string) time.Duration {
	108	+	if v := getenv(matcherTimeoutKey); v != "" {
	109	+	if d, ok := parseTimeSpan(v); ok && d > 0 {
	110	+	return d
	111	+	}
	112	+	}
	113	+	return time.Second
	114	+	}
	115	+
	116	+	type outputManager struct {
	117	+	s *stepRun
	118	+	// cancel is closed when the step is cancelled or times out: the matchers
	119	+	// then stop (see stopped). Nil means never.
	120	+	cancel <-chan struct{}
	121	+	root *matcherRoot
	122	+	timeout time.Duration
	123	+
	124	+	mu sync.Mutex
	125	+	matchers []*issueMatcher
	126	+	dirMap map[string]string // directory -> repository path ("" = none)
	127	+	hasDir map[string]bool
	128	+	}
	129	+
	130	+	// newOutputManager subscribes to the matchers of the job.
	131	+	//
	132	+	// cancel is the cancellation channel of the step (the one the process gets):
	133	+	// once it is closed no matcher runs any more. The runner has no such rule, but
	134	+	// its worker waits for the output of a step with the step's cancellation
	135	+	// token, and a pile of lines against catastrophic patterns (1 s each, 3
	136	+	// attempts, per matcher) would hold a step past its timeout for minutes.
	137	+	func newOutputManager(s stepRun, cancel <-chan struct{}) outputManager {
	138	+	o := &outputManager{s: s, cancel: cancel, root: s.j.matchers, timeout: matcherTimeout(s.j.getenv), dirMap: map[string]string{}, hasDir: map[string]bool{}}
	139	+	o.mu.Lock()
	140	+	o.root.subscribe(o)
	141	+	for _, c := range o.root.snapshot() {
	142	+	if m, err := newIssueMatcher(c, o.timeout); err == nil {
	143	+	o.matchers = append(o.matchers, m)
	144	+	}
	145	+	}
	146	+	o.mu.Unlock()
	147	+	return o
	148	+	}
	149	+
	150	+	// errStopped is the result of a match that was abandoned because the step was
	151	+	// cancelled.
	152	+	var errStopped = msgError("matching stopped: the step was cancelled")
	153	+
	154	+	// runMatch is m.match, abandoned when the step is cancelled while it runs: the
	155	+	// engine cannot be interrupted, so it goes on in its goroutine until its own
	156	+	// timeout, but the step does not wait for it and the matcher is not used again
	157	+	// (stopped is true from then on).
	158	+	func (o outputManager) runMatch(m issueMatcher, line string) (*issueMatch, error) {
	159	+	if o.cancel == nil {
	160	+	return m.match(line)
	161	+	}
	162	+	type result struct {
	163	+	m *issueMatch
	164	+	err error
	165	+	}
	166	+	ch := make(chan result, 1)
	167	+	go func() {
	168	+	r, err := m.match(line)
	169	+	ch <- result{r, err}
	170	+	}()
	171	+	select {
	172	+	case r := <-ch:
	173	+	return r.m, r.err
	174	+	case <-o.cancel:
	175	+	return nil, errStopped
	176	+	}
	177	+	}
	178	+
	179	+	// stopped reports whether the step was cancelled.
	180	+	func (o *outputManager) stopped() bool {
	181	+	if o.cancel == nil {
	182	+	return false
	183	+	}
	184	+	select {
	185	+	case <-o.cancel:
	186	+	return true
	187	+	default:
	188	+	return false
	189	+	}
	190	+	}
	191	+
	192	+	func (o *outputManager) dispose() { o.root.unsubscribe(o) }
	193	+
	194	+	// matcherChanged is OnMatcherChanged: the matcher goes first, the others of
	195	+	// the same owner (ignoring case) go. A config without patterns only removes.
	196	+	func (o outputManager) matcherChanged(c matcherConfig) {
	197	+	o.mu.Lock()
	198	+	defer o.mu.Unlock()
	199	+	var next []*issueMatcher
	200	+	if len(c.Patterns) > 0 {
	201	+	if m, err := newIssueMatcher(c, o.timeout); err == nil {
	202	+	next = append(next, m)
	203	+	}
	204	+	}
	205	+	for _, m := range o.matchers {
	206	+	if !strings.EqualFold(m.owner, c.Owner) {
	207	+	next = append(next, m)
	208	+	}
	209	+	}
	210	+	o.matchers = next
	211	+	}
	212	+
	213	+	func (o outputManager) removeMatcher(m issueMatcher) {
	214	+	o.mu.Lock()
	215	+	defer o.mu.Unlock()
	216	+	var next []*issueMatcher
	217	+	for _, x := range o.matchers {
	218	+	if x != m {
	219	+	next = append(next, x)
	220	+	}
	221	+	}
	222	+	o.matchers = next
	223	+	}
	224	+
	225	+	// onData is OutputManager.OnDataReceived.
	226	+	func (o *outputManager) onData(line string) {
	227	+	s := o.s
	228	+	// ## commands
	229	+	if line != "" && (strings.Contains(line, "##[") \|\| strings.Contains(line, "::")) {
	230	+	if s.cmds.TryProcess(line) {
	231	+	return
	232	+	}
	233	+	}
	234	+	// Strip runner-controlled markers from user output to prevent injection.
	235	+	if strings.Contains(line, "##[start-action") \|\| strings.Contains(line, "##[end-action") {
	236	+	line = strings.ReplaceAll(strings.ReplaceAll(line, "##[start-action", `##[\start-action`), "##[end-action", `##[\end-action`)
	237	+	}
	238	+	// Problem matchers.
	239	+	o.mu.Lock()
	240	+	matchers := append([]*issueMatcher(nil), o.matchers...)
	241	+	o.mu.Unlock()
	242	+	if len(matchers) > 0 && !o.stopped() {
	243	+	stripped := line
	244	+	if strings.Contains(line, colorCodePrefix) {
	245	+	stripped, _ = colorCodeRegex.Replace(line, "", -1, -1)
	246	+	}
	247	+	for _, m := range matchers {
	248	+	var match *issueMatch
	249	+	for attempt := 1; attempt <= maxMatcherAttempts; attempt++ {
	250	+	if o.stopped() {
	251	+	break // the lines that are left are only logged
	252	+	}
	253	+	mt, err := o.runMatch(m, stripped)
	254	+	if err == nil {
	255	+	match = mt
	256	+	break
	257	+	}
	258	+	if o.stopped() {
	259	+	break // a timeout that the cancellation caused counts for nothing
	260	+	}
	261	+	if attempt < maxMatcherAttempts {
	262	+	s.Debug(fmt.Sprintf("Timeout processing issue matcher '%s' against line '%s'. Exception: System.Text.RegularExpressions.RegexMatchTimeoutException: %s", m.owner, stripped, err.Error()))
	263	+	} else {
	264	+	s.j.addIssueFor(s, issue{Level: LevelWarning, Message: fmt.Sprintf("Removing issue matcher '%s'. Matcher failed %d times. Error: %s", m.owner, maxMatcherAttempts, err.Error())})
	265	+	o.removeMatcher(m)
	266	+	}
	267	+	}
	268	+	if match != nil {
	269	+	// Reset other matchers.
	270	+	for _, other := range matchers {
	271	+	if other != m {
	272	+	other.reset()
	273	+	}
	274	+	}
	275	+	if is, ok := o.convertToIssue(match); ok {
	276	+	is.LogText = stripped
	277	+	s.j.addIssueFor(s, is)
	278	+	return
	279	+	}
	280	+	}
	281	+	}
	282	+	}
	283	+	// Regular output.
	284	+	s.Out(line)
	285	+	}
	286	+
	287	+	// convertToIssue is OutputManager.ConvertToIssue (:196-327).
	288	+	func (o outputManager) convertToIssue(m issueMatch) (issue, bool) {
	289	+	s := o.s
	290	+	if strings.TrimFunc(m.message.s, unicode.IsSpace) == "" {
	291	+	s.Debug("Skipping logging an issue for the matched line because the message is empty.")
	292	+	return issue{}, false
	293	+	}
	294	+	var level AnnotationLevel
	295	+	switch strings.ToLower(m.severity.s) {
	296	+	case "", "error":
	297	+	level = LevelFailure
	298	+	case "warning":
	299	+	level = LevelWarning
	300	+	case "notice":
	301	+	level = LevelNotice
	302	+	default:
	303	+	s.Debug(fmt.Sprintf("Skipped logging an issue for the matched line because the severity '%s' is not supported.", m.severity.s))
	304	+	return issue{}, false
	305	+	}
	306	+	is := issue{Level: level, Message: m.message.s, Props: map[string]string{}}
	307	+	// unsigned parses like int.TryParse(NumberStyles.None): digits only.
	308	+	unsigned := func(v string) (string, bool) {
	309	+	for _, r := range v {
	310	+	if r < '0' \|\| r > '9' {
	311	+	return "", false
	312	+	}
	313	+	}
	314	+	n, err := strconv.ParseInt(v, 10, 32)
	315	+	if err != nil \|\| v == "" {
	316	+	return "", false
	317	+	}
	318	+	return strconv.FormatInt(n, 10), true
	319	+	}
	320	+	if m.line.s != "" {
	321	+	if n, ok := unsigned(m.line.s); ok {
	322	+	is.Props["line"] = n
	323	+	} else {
	324	+	s.Debug(fmt.Sprintf("Unable to parse line number '%s'", m.line.s))
	325	+	}
	326	+	}
	327	+	if m.column.s != "" {
	328	+	if n, ok := unsigned(m.column.s); ok {
	329	+	is.Props["col"] = n
	330	+	} else {
	331	+	s.Debug(fmt.Sprintf("Unable to parse column number '%s'", m.column.s))
	332	+	}
	333	+	}
	334	+	if c := strings.TrimFunc(m.code.s, unicode.IsSpace); c != "" {
	335	+	is.Props["code"] = c
	336	+	}
	337	+	// File.
	338	+	if strings.TrimFunc(m.file.s, unicode.IsSpace) != "" {
	339	+	file := m.file.s
	340	+	// Root using fromPath.
	341	+	if strings.TrimFunc(m.fromPath.s, unicode.IsSpace) != "" && !filepath.IsAbs(file) {
	342	+	if dir := filepath.Dir(m.fromPath.s); dir != "." && dir != "" {
	343	+	file = filepath.Join(dir, file)
	344	+	}
	345	+	}
	346	+	// Root using workspace.
	347	+	if !filepath.IsAbs(file) {
	348	+	file = filepath.Join(s.Workspace(), file)
	349	+	}
	350	+	file = filepath.Clean(file)
	351	+	if st, err := os.Stat(file); err == nil && !st.IsDir() {
	352	+	if repo := o.repositoryPath(file, 0); repo != "" {
	353	+	rel := strings.TrimLeft(file[len(repo):], "/")
	354	+	is.Props["file"] = rel
	355	+	} else {
	356	+	s.Debug(fmt.Sprintf("Dropping file value '%s'. Path is not under the workflow repo.", file))
	357	+	}
	358	+	} else {
	359	+	s.Debug(fmt.Sprintf("Dropping file value '%s'. Path does not exist", file))
	360	+	}
	361	+	}
	362	+	return is, true
	363	+	}
	364	+
	365	+	// repositoryPath is OutputManager.GetRepositoryPath: the closest directory
	366	+	// above filePath that has a .git/config naming the repository of the job.
	367	+	func (o *outputManager) repositoryPath(filePath string, recursion int) string {
	368	+	if len(o.dirMap) > 100 {
	369	+	o.dirMap, o.hasDir = map[string]string{}, map[string]bool{}
	370	+	}
	371	+	dir := filepath.Dir(filePath)
	372	+	if dir == filePath \|\| dir == "." \|\| recursion > repoPathFailsafe {
	373	+	return ""
	374	+	}
	375	+	if o.hasDir[dir] {
	376	+	return o.dirMap[dir]
	377	+	}
	378	+	repo := ""
	379	+	gitConfig := filepath.Join(dir, ".git", "config")
	380	+	if st, err := os.Stat(gitConfig); err == nil && !st.IsDir() {
	381	+	serverURL := o.s.j.githubValue("server_url")
	382	+	if serverURL == "" {
	383	+	serverURL = "https://github.com"
	384	+	}
	385	+	host := serverURL
	386	+	if i := strings.Index(host, "://"); i >= 0 {
	387	+	host = host[i+3:]
	388	+	}
	389	+	if i := strings.IndexAny(host, "/:"); i >= 0 {
	390	+	host = host[:i]
	391	+	}
	392	+	nameWithOwner := o.s.j.githubValue("repository")
	393	+	patterns := []string{"url = " + serverURL + "/" + nameWithOwner, "url = git@" + host + ":" + nameWithOwner + ".git"}
	394	+	if b, err := os.ReadFile(gitConfig); err == nil {
	395	+	for _, l := range strings.Split(string(b), "\n") {
	396	+	l = strings.TrimFunc(l, unicode.IsSpace)
	397	+	for _, p := range patterns {
	398	+	if strings.EqualFold(l, p) {
	399	+	repo = dir
	400	+	}
	401	+	}
	402	+	}
	403	+	} else {
	404	+	o.s.Debug(fmt.Sprintf("Error when attempting to determine whether the path '%s' is under the workflow repository: %v", filePath, err))
	405	+	}
	406	+	} else {
	407	+	repo = o.repositoryPath(dir, recursion+1)
	408	+	}
	409	+	o.dirMap[dir], o.hasDir[dir] = repo, true
	410	+	return repo
	411	+	}

M internal/executor/report.go +43 -0


@@ -48,3 +48,46 @@ type Result struct {
48	// told to stop (see ErrShutdown).	48		// told to stop (see ErrShutdown).
49	RunnerShutdown bool	49		RunnerShutdown bool
50	}	50		}
		51	+
		52	+	// AnnotationLevel is the severity of an annotation.
		53	+	type AnnotationLevel string
		54	+
		55	+	// Levels, with the names of GitHub's check run annotations.
		56	+	const (
		57	+	LevelNotice AnnotationLevel = "notice"
		58	+	LevelWarning AnnotationLevel = "warning"
		59	+	LevelFailure AnnotationLevel = "failure" // ::error and an error that the runner itself logs
		60	+	)
		61	+
		62	+	// Annotation is a message attached to a step, produced by ::notice,
		63	+	// ::warning, ::error, a problem matcher or an error the runner logs, and
		64	+	// already masked. The executor keeps at most 10 per level per step.
		65	+	type Annotation struct {
		66	+	Level AnnotationLevel
		67	+	Title, Message, File string
		68	+	StartLine, EndLine int32
		69	+	StartColumn int32
		70	+	EndColumn int32
		71	+	}
		72	+
		73	+	// StepResults is what a step leaves besides its log, reported just before
		74	+	// StepCompleted.
		75	+	type StepResults struct {
		76	+	// Outcome is steps.<id>.outcome: the result before continue-on-error.
		77	+	Outcome Conclusion
		78	+	// Annotations is the whole list of the step, replacing any earlier one. It
		79	+	// is empty when ci.annotations is not available (Config.SendAnnotations).
		80	+	Annotations []Annotation
		81	+	// Summary is the masked GITHUB_STEP_SUMMARY of the step, HasSummary says
		82	+	// whether there is one. Empty when ci.summaries is not available
		83	+	// (Config.SendSummaries).
		84	+	Summary string
		85	+	HasSummary bool
		86	+	}
		87	+
		88	+	// StepResultReporter is implemented by a Reporter that wants the results of
		89	+	// the steps. StepResults(n) is called once for each step of the workflow,
		90	+	// before StepCompleted(n) and under the same serialisation.
		91	+	type StepResultReporter interface {
		92	+	StepResults(number int, r StepResults)
		93	+	}

A internal/executor/results.go +352 -0

@@ -0,0 +1,352 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"context"
	7	+	"fmt"
	8	+	"io"
	9	+	"os"
	10	+	"strings"
	11	+	"sync/atomic"
	12	+	"time"
	13	+
	14	+	"bnema.dev/ermite-actions/template"
	15	+	)
	16	+
	17	+	// What a step leaves besides its log: annotations, summary, outcome, saved
	18	+	// state. The pieces that the steps of phase F share (embedded steps of a
	19	+	// composite action, state of an action) are the fields marked below.
	20	+
	21	+	// stepScope is what a step that runs inside another one (a step of a
	22	+	// composite action) shares with the step of the workflow that uses the action.
	23	+	// The zero value is a step of the workflow.
	24	+	type stepScope struct {
	25	+	// issues, when set, is the collector of the outer step: the issues of an
	26	+	// embedded step count against its limits (ExecutionContext.AddIssue,
	27	+	// :838). Embedded is true then.
	28	+	issues *issueCollector
	29	+	embedded bool
	30	+	// stateKey names the intra-action state the step saves to (SaveState). Empty
	31	+	// means the step's own number.
	32	+	stateKey string
	33	+	}
	34	+
	35	+	// AddIssue is ExecutionContext.AddIssue for the step.
	36	+	func (s *stepRun) AddIssue(is issue) { s.j.addIssueFor(s, is) }
	37	+
	38	+	func (j job) addIssueFor(s stepRun, is issue) {
	39	+	j.addIssue(s.num, s.scope.issues, s.scope.embedded, is)
	40	+	}
	41	+
	42	+	// Workspace is github.workspace.
	43	+	func (s *stepRun) Workspace() string { return s.j.githubValue("workspace") }
	44	+
	45	+	func (j *job) githubValue(k string) string {
	46	+	j.mu.Lock()
	47	+	defer j.mu.Unlock()
	48	+	return j.state.GitHub(k)
	49	+	}
	50	+
	51	+	// AddMask is SecretMasker.AddValue.
	52	+	func (s *stepRun) AddMask(v string) { s.j.addMask(v) }
	53	+
	54	+	// addMask registers values with the masker of the job, with their encodings
	55	+	// (SecretMasker.AddValue). It is the one way to add a secret after the job
	56	+	// started (add-mask, a stop-commands token, the token of an action archive): it
	57	+	// only adds, the masker is never replaced, so the text that other goroutines
	58	+	// mask meanwhile loses no value.
	59	+	func (j *job) addMask(values ...string) {
	60	+	m := j.masker.Load()
	61	+	for _, v := range values {
	62	+	m.add(v)
	63	+	}
	64	+	}
	65	+
	66	+	// Matchers is the root of the problem matchers of the job.
	67	+	func (s stepRun) Matchers() matcherRoot { return s.j.matchers }
	68	+
	69	+	// maxMatcherFile bounds a problem matcher file.
	70	+	const maxMatcherFile = 1 << 20
	71	+
	72	+	// ReadMatcherFile reads a problem matcher file.
	73	+	func (s *stepRun) ReadMatcherFile(path string) ([]byte, error) {
	74	+	f, err := os.Open(path)
	75	+	if err != nil {
	76	+	return nil, err
	77	+	}
	78	+	defer func() { _ = f.Close() }()
	79	+	b, err := io.ReadAll(io.LimitReader(f, maxMatcherFile+1))
	80	+	if err != nil {
	81	+	return nil, err
	82	+	}
	83	+	if len(b) > maxMatcherFile {
	84	+	return nil, ghErrorf("The problem matcher file is larger than %d bytes", maxMatcherFile)
	85	+	}
	86	+	return b, nil
	87	+	}
	88	+
	89	+	func (j *job) getenv(k string) string {
	90	+	if j.cfg.Getenv != nil {
	91	+	return j.cfg.Getenv(k)
	92	+	}
	93	+	return os.Getenv(k)
	94	+	}
	95	+
	96	+	// SaveState is the state of an action step (save-state and GITHUB_STATE): kept
	97	+	// per step so that the post step of the action can read it as STATE_<name>
	98	+	// (ActionCommandManager.cs:384-398). A step that is not an action only fills
	99	+	// it; the runner does the same.
	100	+	func (s *stepRun) SaveState(name, value string) { s.j.saveState(s.stateKey(), name, value) }
	101	+
	102	+	func (s *stepRun) stateKey() string {
	103	+	if s.scope.stateKey != "" {
	104	+	return s.scope.stateKey
	105	+	}
	106	+	return fmt.Sprint(s.num)
	107	+	}
	108	+
	109	+	// intraState is IntraActionState: a Dictionary<string, string> with an
	110	+	// OrdinalIgnoreCase comparer. A name that is already there keeps the spelling
	111	+	// it was first saved with and takes the new value (the indexer of Dictionary
	112	+	// replaces the value, not the key), and the entries enumerate in the order
	113	+	// they were added: ActionRunner.cs:255-258 sets STATE_<key> from that
	114	+	// enumeration, so the spelling of the first save-state is the one the action
	115	+	// sees.
	116	+	type intraState struct {
	117	+	keys []string // spelling and order of first insertion
	118	+	vals map[string]string
	119	+	}
	120	+
	121	+	func (st *intraState) set(name, value string) {
	122	+	if st.vals == nil {
	123	+	st.vals = map[string]string{}
	124	+	}
	125	+	lo := strings.ToLower(name)
	126	+	if _, ok := st.vals[lo]; !ok {
	127	+	st.keys = append(st.keys, name)
	128	+	}
	129	+	st.vals[lo] = value
	130	+	}
	131	+
	132	+	// Pair is one saved name (as first spelled) and its value.
	133	+	func (st *intraState) pairs() []Pair {
	134	+	out := make([]Pair, 0, len(st.keys))
	135	+	for _, k := range st.keys {
	136	+	out = append(out, Pair{k, st.vals[strings.ToLower(k)]})
	137	+	}
	138	+	return out
	139	+	}
	140	+
	141	+	func (j *job) saveState(key, name, value string) {
	142	+	j.issuesMu.Lock()
	143	+	defer j.issuesMu.Unlock()
	144	+	if j.states == nil {
	145	+	j.states = map[string]*intraState{}
	146	+	}
	147	+	st := j.states[key]
	148	+	if st == nil {
	149	+	st = &intraState{}
	150	+	j.states[key] = st
	151	+	}
	152	+	st.set(name, value)
	153	+	}
	154	+
	155	+	// intraActionState returns the state saved under key (the number of the step,
	156	+	// or the stateKey of its scope) as the runner enumerates it: names as first
	157	+	// spelled, in the order they were first saved. Phase F sets STATE_<name> from
	158	+	// it for the pre, main and post stages of the action.
	159	+	func (j *job) intraActionState(key string) []Pair {
	160	+	j.issuesMu.Lock()
	161	+	defer j.issuesMu.Unlock()
	162	+	if st := j.states[key]; st != nil {
	163	+	return st.pairs()
	164	+	}
	165	+	return nil
	166	+	}
	167	+
	168	+	// Summary receives GITHUB_STEP_SUMMARY after the step (see processStepSummary).
	169	+	//
	170	+	// The server keeps one summary per step of the workflow. The steps inside a
	171	+	// composite action each have a summary file in the runner (uploaded under the
	172	+	// id of the embedded step); here they are concatenated, in order, under the
	173	+	// step that uses the action.
	174	+	func (s *stepRun) Summary(markdown string) {
	175	+	j := s.j
	176	+	j.issuesMu.Lock()
	177	+	defer j.issuesMu.Unlock()
	178	+	if j.summaries == nil {
	179	+	j.summaries = map[int]string{}
	180	+	}
	181	+	if s.scope.embedded {
	182	+	markdown = j.summaries[s.num] + markdown
	183	+	if len(markdown) > stepSummaryLimit {
	184	+	return // over the limit of the contract: the first ones stay
	185	+	}
	186	+	}
	187	+	j.summaries[s.num] = markdown
	188	+	}
	189	+
	190	+	// MaskText masks text with the secrets known now.
	191	+	func (s *stepRun) MaskText(t string) string { return s.j.mask(t) }
	192	+
	193	+	// summarySink is implemented by the Sink of a step that keeps summaries.
	194	+	type summarySink interface{ Summary(markdown string) }
	195	+
	196	+	// recordOutcome keeps steps.<id>.outcome of a step for StepResults.
	197	+	func (j *job) recordOutcome(num int, c Conclusion) {
	198	+	j.issuesMu.Lock()
	199	+	defer j.issuesMu.Unlock()
	200	+	if j.outcomes == nil {
	201	+	j.outcomes = map[int]Conclusion{}
	202	+	}
	203	+	j.outcomes[num] = c
	204	+	}
	205	+
	206	+	// flushStepResults hands the results of step n to the reporter, before the step
	207	+	// completes. Called with the serialisation of the reporter not held.
	208	+	func (j *job) flushStepResults(next Reporter, n int, c Conclusion) {
	209	+	rr, ok := next.(StepResultReporter)
	210	+	if !ok {
	211	+	return
	212	+	}
	213	+	j.issuesMu.Lock()
	214	+	outcome, has := j.outcomes[n]
	215	+	summary, hasSummary := j.summaries[n]
	216	+	delete(j.summaries, n)
	217	+	coll := j.collectors[n]
	218	+	j.issuesMu.Unlock()
	219	+	if !has {
	220	+	outcome = c
	221	+	}
	222	+	r := StepResults{Outcome: outcome}
	223	+	if coll != nil && j.cfg.SendAnnotations {
	224	+	r.Annotations = coll.result()
	225	+	}
	226	+	if hasSummary && j.cfg.SendSummaries {
	227	+	r.Summary, r.HasSummary = summary, true
	228	+	}
	229	+	rr.StepResults(n, r)
	230	+	}
	231	+
	232	+	// logCanceled logs the cancellation of the process of a step
	233	+	// (StepsRunner.cs:333-337 logs the exception of a cancelled step), unless the
	234	+	// step timed out: then StepsRunner logs the timeout message instead.
	235	+	func (s *stepRun) logCanceled() {
	236	+	if s.timedOut.Load() && !s.j.cancelRequested() {
	237	+	return
	238	+	}
	239	+	s.j.errorf(s.num, "The operation was canceled.")
	240	+	}
	241	+
	242	+	func (j *job) cancelRequested() bool {
	243	+	select {
	244	+	case <-j.cancel.Done():
	245	+	return true
	246	+	default:
	247	+	return false
	248	+	}
	249	+	}
	250	+
	251	+	// ---- timeout-minutes
	252	+
	253	+	// timedOutFlag is the marker of a step that reached its timeout.
	254	+	type timedOutFlag = atomic.Bool
	255	+
	256	+	// stepTimeoutMessage is StepsRunner.cs:328.
	257	+	func stepTimeoutMessage(name string, minutes int) string {
	258	+	return fmt.Sprintf("The action '%s' has timed out after %d minutes.", name, minutes)
	259	+	}
	260	+
	261	+	// ---- step summary
	262	+
	263	+	// summaryContent is what CreateStepSummaryCommand uploads: the lines of the
	264	+	// file, each masked, each ended by a line feed (StreamReader.ReadLine and
	265	+	// StreamWriter.WriteLine; ProcessCommand, FileCommandManager.cs:253-261).
	266	+	func summaryContent(text string, mask func(string) string) string {
	267	+	var sb strings.Builder
	268	+	for _, l := range splitLines(text) {
	269	+	sb.WriteString(mask(l))
	270	+	sb.WriteByte('\n')
	271	+	}
	272	+	return sb.String()
	273	+	}
	274	+
	275	+	// maxStepTimeoutMinutes bounds the timeout so that the duration fits.
	276	+	const maxStepTimeoutMinutes = 1 << 24
	277	+
	278	+	// stepTimeout is PipelineTemplateEvaluator.EvaluateStepTimeout and
	279	+	// ConvertToStepTimeout: the number is truncated to an int; zero, negative and
	280	+	// absent values mean no timeout. An expression that fails logs the runner's
	281	+	// two errors and the step runs without timeout (StepsRunner.cs:266-273).
	282	+	func (j job) stepTimeout(s stepRun) int {
	283	+	tok := s.st.TimeoutMinutes
	284	+	if tok == nil {
	285	+	return 0
	286	+	}
	287	+	j.mu.Lock()
	288	+	f, err := template.EvaluateNumber(context.Background(), tok, j.evalEnv(s.env))
	289	+	j.mu.Unlock()
	290	+	if err != nil {
	291	+	j.errorf(s.num, "An error occurred when attempting to determine the step timeout.")
	292	+	j.errorf(s.num, "%s", templateNotValid(err, true))
	293	+	return 0
	294	+	}
	295	+	switch {
	296	+	case f != f \|\| f < 1:
	297	+	return 0
	298	+	case f > maxStepTimeoutMinutes:
	299	+	return maxStepTimeoutMinutes
	300	+	}
	301	+	return int(f)
	302	+	}
	303	+
	304	+	// ---- hook points for steps that contain steps (phase F)
	305	+	//
	306	+	// A step of the workflow is run by runStep; a composite action runs its inner
	307	+	// steps itself. What an inner step shares with the step that contains it is
	308	+	// named by a stepScope, and what its lifecycle needs from the commands is:
	309	+	//
	310	+	// - embeddedScope(outer, stateKey): the scope of an inner step. Its issues
	311	+	// go to the collector of the outer step (counted against its limits when
	312	+	// the outer step completes) and its summary is appended to the outer
	313	+	// step's; its save-state goes to the state of stateKey.
	314	+	// - newOutputManager(s, cancel): one per process of a step (inner or not),
	315	+	// with the cancellation channel the process gets; call dispose when the
	316	+	// process is over.
	317	+	// - armStepTimeout / stepTimedOut: the timeout of a step, inner or not,
	318	+	// around the run of its body (see runStep).
	319	+	// - addMask: add a secret.
	320	+
	321	+	// embeddedScope is the scope of a step inside the step outer.
	322	+	func (j job) embeddedScope(outer stepRun, stateKey string) stepScope {
	323	+	return stepScope{issues: j.collector(outer.num), embedded: true, stateKey: stateKey}
	324	+	}
	325	+
	326	+	// armStepTimeout starts the timeout-minutes timer of the step (StepsRunner.
	327	+	// RunStepAsync, :280-296). When it fires, the step is marked timed out and
	328	+	// cancel is called (the same cancellation as a job cancel: SIGINT, SIGTERM,
	329	+	// SIGKILL). It returns the function that stops the timer and the number of
	330	+	// minutes, 0 for none.
	331	+	func (j job) armStepTimeout(s stepRun, cancel func()) (stop func(), minutes int) {
	332	+	minutes = j.stepTimeout(s)
	333	+	if minutes <= 0 {
	334	+	return func() {}, 0
	335	+	}
	336	+	t := time.AfterFunc(time.Duration(minutes)*time.Minute+j.cfg.StepTimeoutSkew, func() {
	337	+	s.timedOut.Store(true)
	338	+	cancel()
	339	+	})
	340	+	return func() { t.Stop() }, minutes
	341	+	}
	342	+
	343	+	// stepTimedOut turns the result of a step whose own timer fired (and not the
	344	+	// job's cancellation) into a failure with the runner's message
	345	+	// (StepsRunner.cs:323-330). Other results pass through.
	346	+	func (j job) stepTimedOut(s stepRun, r stepResult, minutes int) stepResult {
	347	+	if r == resCanceled && s.timedOut.Load() && !j.cancelRequested() {
	348	+	j.errorf(s.num, "%s", stepTimeoutMessage(s.name, minutes))
	349	+	return resFailed
	350	+	}
	351	+	return r
	352	+	}

A internal/executor/results_test.go +432 -0

@@ -0,0 +1,432 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package executor
	4	+
	5	+	import (
	6	+	"fmt"
	7	+	"strings"
	8	+	"testing"
	9	+	"time"
	10	+	)
	11	+
	12	+	const matcherSetup = ` - name: prepare
	13	+	run: \|
	14	+	mkdir -p src
	15	+	git init -q .
	16	+	git remote add origin "$GITHUB_SERVER_URL/$GITHUB_REPOSITORY"
	17	+	echo x > src/main.go
	18	+	cat > m.json <<'JSON'
	19	+	{"problemMatcher":[{"owner":"go","severity":"warning","pattern":[{"regexp":"^(.+):(\\d+):(\\d+): (error\|warning)?: ?(.*)$","file":1,"line":2,"column":3,"severity":4,"message":5}]}]}
	20	+	JSON
	21	+	`
	22	+
	23	+	// The workspace of runLocal is hello/hello under the home; the setup step
	24	+	// runs in it, so the repository check of OutputManager.GetRepositoryPath finds
	25	+	// .git/config there.
	26	+	func TestProblemMatcherEndToEnd(t *testing.T) {
	27	+	needTools(t, "bash", "git")
	28	+	rr, res := runResults(t, wfHead+` steps:
	29	+	`+matcherSetup+` - name: match
	30	+	run: \|
	31	+	echo "::add-matcher::m.json"
	32	+	echo "src/main.go:12:5: error: bad thing"
	33	+	echo "src/main.go:7:1: : just a warning"
	34	+	echo "src/missing.go:1:1: error: no such file"
	35	+	echo "nothing here"
	36	+	echo "::remove-matcher owner=go::"
	37	+	echo "src/main.go:12:5: error: not matched"
	38	+	`, nil)
	39	+	if res.Conclusion != ConclusionSuccess {
	40	+	t.Fatalf("%+v", res)
	41	+	}
	42	+	got := rr.results[3].Annotations
	43	+	want := []Annotation{
	44	+	{Level: LevelFailure, Message: "bad thing", File: "src/main.go", StartLine: 12, StartColumn: 5},
	45	+	{Level: LevelWarning, Message: "just a warning", File: "src/main.go", StartLine: 7, StartColumn: 1},
	46	+	{Level: LevelFailure, Message: "no such file", StartLine: 1, StartColumn: 1}, // the file does not exist: dropped
	47	+	}
	48	+	if fmt.Sprint(got) != fmt.Sprint(want) {
	49	+	t.Errorf("annotations\n got %+v\nwant %+v", got, want)
	50	+	}
	51	+	log := logOf(rr.step(t, "match"))
	52	+	for _, w := range []string{"##[error]src/main.go:12:5: error: bad thing", "##[warning]src/main.go:7:1: : just a warning", "\nnothing here\n", "\nsrc/main.go:12:5: error: not matched"} {
	53	+	if !strings.Contains(log+"\n", w) {
	54	+	t.Errorf("log lacks %q:\n%s", w, log)
	55	+	}
	56	+	}
	57	+	// the matched lines are not logged a second time as plain text
	58	+	_, body, _ := strings.Cut(log, "##[endgroup]\n")
	59	+	if strings.Count(body, "bad thing") != 1 {
	60	+	t.Errorf("a matched line is logged twice:\n%s", log)
	61	+	}
	62	+	}
	63	+
	64	+	// AC6b through a whole step: the catastrophic matcher is retried 3 times (one
	65	+	// second each), removed with the runner's warning, and the step goes on; the
	66	+	// other matcher keeps working. OutputManager.Remove only edits the list of the
	67	+	// step (OutputManager.cs:300-313) while the next step starts from the matchers
	68	+	// of the job (ExecutionContext.GetMatchers), so the next step meets the
	69	+	// matcher again and removes it again after 3 more timeouts.
	70	+	func TestCatastrophicMatcherIsRemovedAfterThreeTimeouts(t *testing.T) {
	71	+	needTools(t, "bash")
	72	+	start := time.Now()
	73	+	rr, res := runResults(t, wfHead+` steps:
	74	+	- name: prepare
	75	+	run: \|
	76	+	cat > bad.json <<'JSON'
	77	+	{"problemMatcher":[{"owner":"catastrophic","pattern":[{"regexp":"^((a+)+)$","message":1}]}]}
	78	+	JSON
	79	+	cat > good.json <<'JSON'
	80	+	{"problemMatcher":[{"owner":"good","severity":"warning","pattern":[{"regexp":"^good: (.+)$","message":1}]}]}
	81	+	JSON
	82	+	- name: catastrophic
	83	+	run: \|
	84	+	echo "::add-matcher::bad.json"
	85	+	echo "::add-matcher::good.json"
	86	+	echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
	87	+	echo "good: still alive"
	88	+	echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
	89	+	- name: next step
	90	+	run: \|
	91	+	echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
	92	+	echo "good: next step"
	93	+	`, nil)
	94	+	took := time.Since(start)
	95	+	if res.Conclusion != ConclusionSuccess {
	96	+	t.Fatalf("%+v", res)
	97	+	}
	98	+	if took > 15*time.Second {
	99	+	t.Errorf("the step stalled: %v", took)
	100	+	}
	101	+	log := logOf(rr.step(t, "catastrophic"))
	102	+	const removing = "##[warning]Removing issue matcher 'catastrophic'. Matcher failed 3 times. Error: The Regex engine has timed out while trying to match a pattern to an input string."
	103	+	if strings.Count(log, removing) != 1 {
	104	+	t.Errorf("removal message missing or repeated:\n%s", log)
	105	+	}
	106	+	if !strings.Contains(log, "\naaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!\n##[warning]good: still alive") && !strings.Contains(log, "##[warning]good: still alive") {
	107	+	t.Errorf("the good matcher stopped working:\n%s", log)
	108	+	}
	109	+	// Only one removal: the second long line did not time out again.
	110	+	if n := len(rr.results[3].Annotations); n != 2 {
	111	+	t.Errorf("%d annotations: %+v", n, rr.results[3].Annotations)
	112	+	}
	113	+	next := logOf(rr.step(t, "next step"))
	114	+	if strings.Count(next, "Removing issue matcher 'catastrophic'") != 1 \|\| !strings.Contains(next, "##[warning]good: next step") {
	115	+	t.Errorf("next step:\n%s", next)
	116	+	}
	117	+	}
	118	+
	119	+	func TestMatcherTimeoutFromEnvironment(t *testing.T) {
	120	+	needTools(t, "bash")
	121	+	start := time.Now()
	122	+	rr, _ := runResults(t, wfHead+` steps:
	123	+	- name: fast
	124	+	run: \|
	125	+	echo '{"problemMatcher":[{"owner":"c","pattern":[{"regexp":"^((a+)+)$","message":1}]}]}' > bad.json
	126	+	echo "::add-matcher::bad.json"
	127	+	echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
	128	+	`, func(c *Config) {
	129	+	c.Getenv = func(k string) string { return map[string]string{matcherTimeoutKey: "0:0:0.05"}[k] }
	130	+	})
	131	+	if time.Since(start) > 2500*time.Millisecond {
	132	+	t.Errorf("the timeout of the environment was not used: %v", time.Since(start))
	133	+	}
	134	+	if !strings.Contains(logOf(rr.step(t, "fast")), "Removing issue matcher 'c'") {
	135	+	t.Error(logOf(rr.step(t, "fast")))
	136	+	}
	137	+	}
	138	+
	139	+	func TestAddMatcherErrors(t *testing.T) {
	140	+	needTools(t, "bash")
	141	+	rr, res := runResults(t, wfHead+` steps:
	142	+	- name: bad
	143	+	run: \|
	144	+	echo "::add-matcher::"
	145	+	echo "::remove-matcher::"
	146	+	echo "::remove-matcher owner=x::file.json"
	147	+	echo "::add-matcher::missing.json"
	148	+	- name: invalid
	149	+	if: always()
	150	+	run: \|
	151	+	echo '{"problemMatcher":[{"owner":"m","pattern":[{"regexp":"(","message":1}]}]}' > b.json
	152	+	echo "::add-matcher::b.json"
	153	+	`, nil)
	154	+	if res.Conclusion != ConclusionFailure {
	155	+	t.Fatalf("%+v", res)
	156	+	}
	157	+	log := logOf(rr.step(t, "bad"))
	158	+	for _, w := range []string{
	159	+	"##[warning]File path must be specified.",
	160	+	"##[warning]Either an owner name or a file path must be specified in ##[remove-matcher] command.",
	161	+	"##[warning]Either specify an owner name or a file path in ##[remove-matcher] command. Both values cannot be set.",
	162	+	"##[error]Unable to process command '::add-matcher::missing.json' successfully.",
	163	+	"##[error]Could not find file '",
	164	+	} {
	165	+	if !strings.Contains(log, w) {
	166	+	t.Errorf("log lacks %q:\n%s", w, log)
	167	+	}
	168	+	}
	169	+	if !strings.Contains(logOf(rr.step(t, "invalid")), "##[error]Unable to process command '::add-matcher::b.json' successfully.") {
	170	+	t.Error(logOf(rr.step(t, "invalid")))
	171	+	}
	172	+	}
	173	+
	174	+	func TestStepSummary(t *testing.T) {
	175	+	needTools(t, "bash")
	176	+	rr, _ := runResults(t, wfHead+` steps:
	177	+	- name: write
	178	+	run: \|
	179	+	echo "::add-mask::sekret-value"
	180	+	printf '# Title\nvalue sekret-value\r\nlast line without newline' >> "$GITHUB_STEP_SUMMARY"
	181	+	- name: empty
	182	+	run: 'true'
	183	+	- name: huge
	184	+	run: head -c 1048577 /dev/zero \| tr '\0' x >> "$GITHUB_STEP_SUMMARY"
	185	+	- name: exactly one MiB
	186	+	run: head -c 1048576 /dev/zero \| tr '\0' x >> "$GITHUB_STEP_SUMMARY"
	187	+	`, nil)
	188	+	if r := rr.results[2]; !r.HasSummary \|\| r.Summary != "# Title\nvalue ***\nlast line without newline\n" {
	189	+	t.Errorf("summary %q %v", r.Summary, r.HasSummary)
	190	+	}
	191	+	if rr.results[3].HasSummary {
	192	+	t.Error("no file content, no summary")
	193	+	}
	194	+	if rr.results[4].HasSummary {
	195	+	t.Error("an oversized summary is not sent")
	196	+	}
	197	+	if !strings.Contains(logOf(rr.step(t, "huge")), "##[error]$GITHUB_STEP_SUMMARY upload aborted, supports content up to a size of 1024k, got 1024k.") {
	198	+	t.Errorf("%s", logOf(rr.step(t, "huge"))[:200])
	199	+	}
	200	+	// 1 MiB of x plus one line feed per line is over the limit once rewritten:
	201	+	// the runner adds the "\n"; the contract allows 1 MiB.
	202	+	if r := rr.results[5]; r.HasSummary && len(r.Summary) > stepSummaryLimit {
	203	+	t.Errorf("a summary above the contract limit is sent: %d", len(r.Summary))
	204	+	}
	205	+	}
	206	+
	207	+	func TestSummaryOffWithoutTheFeature(t *testing.T) {
	208	+	needTools(t, "bash")
	209	+	rr, _ := runResults(t, wfHead+" steps:\n - run: echo hi >> \"$GITHUB_STEP_SUMMARY\"\n", func(c *Config) { c.SendSummaries = false })
	210	+	if rr.results[2].HasSummary {
	211	+	t.Error("summary sent without ci.summaries")
	212	+	}
	213	+	}
	214	+
	215	+	func TestStepOutcome(t *testing.T) {
	216	+	needTools(t, "bash")
	217	+	rr, res := runResults(t, wfHead+` steps:
	218	+	- run: exit 1
	219	+	continue-on-error: true
	220	+	- run: 'true'
	221	+	- run: exit 2
	222	+	`, nil)
	223	+	if res.Conclusion != ConclusionFailure {
	224	+	t.Fatal(res)
	225	+	}
	226	+	if r := rr.results[2]; r.Outcome != ConclusionFailure \|\| rr.steps[1].Conclusion != ConclusionSuccess {
	227	+	t.Errorf("continue-on-error: outcome %v conclusion %v", r.Outcome, rr.steps[1].Conclusion)
	228	+	}
	229	+	if r := rr.results[3]; r.Outcome != ConclusionSuccess {
	230	+	t.Errorf("%+v", r)
	231	+	}
	232	+	if r := rr.results[4]; r.Outcome != ConclusionFailure {
	233	+	t.Errorf("%+v", r)
	234	+	}
	235	+	}
	236	+
	237	+	func TestStepTimeout(t *testing.T) {
	238	+	needTools(t, "bash")
	239	+	skew := -(60time.Second - 700time.Millisecond) // one minute becomes 0.7 s
	240	+	rr, res := runResults(t, wfHead+` steps:
	241	+	- name: slow
	242	+	id: slow
	243	+	timeout-minutes: 1
	244	+	run: \|
	245	+	trap 'echo got-int; exit 130' INT
	246	+	echo "before=written" >> "$GITHUB_OUTPUT"
	247	+	sleep 30 & wait
	248	+	- name: after success
	249	+	run: echo "ran after the timeout"
	250	+	- name: after failure
	251	+	if: failure()
	252	+	run: echo "outcome=${{ steps.slow.outcome }} conclusion=${{ steps.slow.conclusion }} status=${{ job.status }} out=${{ steps.slow.outputs.before }}"
	253	+	- name: cancelled()
	254	+	if: cancelled()
	255	+	run: echo "cancelled is true"
	256	+	- name: soft
	257	+	id: soft
	258	+	timeout-minutes: 1
	259	+	continue-on-error: true
	260	+	if: always()
	261	+	run: sleep 30
	262	+	- name: results
	263	+	if: always()
	264	+	run: echo "soft=${{ steps.soft.outcome }}/${{ steps.soft.conclusion }}"
	265	+	- name: fractional
	266	+	timeout-minutes: 0.9
	267	+	run: sleep 1
	268	+	- name: expression
	269	+	timeout-minutes: ${{ fromJSON('0') }}
	270	+	run: echo no timeout
	271	+	`, func(c *Config) { c.StepTimeoutSkew = skew })
	272	+	if res.Conclusion != ConclusionFailure {
	273	+	t.Fatalf("%+v", res)
	274	+	}
	275	+	slow := rr.step(t, "slow")
	276	+	if slow.Conclusion != ConclusionFailure {
	277	+	t.Errorf("conclusion %v", slow.Conclusion)
	278	+	}
	279	+	log := logOf(slow)
	280	+	if !strings.Contains(log, "##[error]The action 'slow' has timed out after 1 minutes.") \|\| strings.Contains(log, "The operation was canceled.") {
	281	+	t.Errorf("log:\n%s", log)
	282	+	}
	283	+	if !strings.Contains(log, "got-int") {
	284	+	t.Errorf("the step did not get SIGINT first:\n%s", log)
	285	+	}
	286	+	if a := rr.results[2].Annotations; len(a) == 0 \|\| a[len(a)-1].Message != "The action 'slow' has timed out after 1 minutes." {
	287	+	t.Errorf("annotations %+v", a)
	288	+	}
	289	+	if rr.results[2].Outcome != ConclusionFailure {
	290	+	t.Error("outcome")
	291	+	}
	292	+	if rr.step(t, "after success").Conclusion != ConclusionSkipped {
	293	+	t.Error("success() is false after a timeout")
	294	+	}
	295	+	if l := logOf(rr.step(t, "after failure")); !strings.HasSuffix(l, "outcome=failure conclusion=failure status=failure out=written") {
	296	+	t.Errorf("after failure: %s", l)
	297	+	}
	298	+	if rr.step(t, "cancelled()").Conclusion != ConclusionSkipped {
	299	+	t.Error("a step timeout is not a cancellation")
	300	+	}
	301	+	if l := logOf(rr.step(t, "results")); !strings.HasSuffix(l, "soft=failure/success") {
	302	+	t.Errorf("results: %s", l)
	303	+	}
	304	+	if rr.step(t, "fractional").Conclusion != ConclusionSkipped && rr.step(t, "fractional").Conclusion != ConclusionSuccess {
	305	+	t.Error("fractional")
	306	+	}
	307	+	}
	308	+
	309	+	func TestStepTimeoutExpressionError(t *testing.T) {
	310	+	needTools(t, "bash")
	311	+	rr, res := runResults(t, wfHead+` steps:
	312	+	- name: bad
	313	+	env:
	314	+	LIMIT: abc
	315	+	timeout-minutes: ${{ env.LIMIT }}
	316	+	run: echo ran
	317	+	`, nil)
	318	+	log := logOf(rr.step(t, "bad"))
	319	+	if !strings.Contains(log, "##[error]An error occurred when attempting to determine the step timeout.") \|\| !strings.Contains(log, "\nran") {
	320	+	t.Errorf("%s", log)
	321	+	}
	322	+	if res.Conclusion != ConclusionFailure && res.Conclusion != ConclusionSuccess {
	323	+	t.Fatal(res)
	324	+	}
	325	+	}
	326	+
	327	+	// save-state keeps the state per action; names are case-insensitive, the
	328	+	// first spelling is the key the action sees (STATE_<key>, ActionRunner.cs:255)
	329	+	// and entries keep the order they were first saved in.
	330	+	func TestSaveStateKeepsTheFirstSpellingAndOrder(t *testing.T) {
	331	+	j := &job{}
	332	+	j.saveState("2", "Foo", "bar")
	333	+	j.saveState("2", "zed", "1")
	334	+	j.saveState("2", "FOO", "baz")
	335	+	j.saveState("3", "x", "y")
	336	+	got := j.intraActionState("2")
	337	+	if fmt.Sprint(got) != fmt.Sprint([]Pair{{"Foo", "baz"}, {"zed", "1"}}) {
	338	+	t.Errorf("%v", got)
	339	+	}
	340	+	if got := j.intraActionState("4"); len(got) != 0 {
	341	+	t.Errorf("%v", got)
	342	+	}
	343	+	}
	344	+
	345	+	// The hook points phase F calls (see results.go): the additive mask API, the
	346	+	// scope of an inner step of a composite action, the timeout helpers.
	347	+	func TestAddMaskIsAdditive(t *testing.T) {
	348	+	j := &job{}
	349	+	j.masker.Store(newMasker("first-secret"))
	350	+	before := j.masker.Load()
	351	+	j.addMask("second-secret", "third-secret")
	352	+	if j.masker.Load() != before {
	353	+	t.Error("the masker was replaced")
	354	+	}
	355	+	for _, v := range []string{"first-secret", "second-secret", "third-secret"} {
	356	+	if j.mask("x "+v) != "x ***" {
	357	+	t.Errorf("%q is not masked", v)
	358	+	}
	359	+	}
	360	+	}
	361	+
	362	+	func TestEmbeddedScopeSharesTheOuterStep(t *testing.T) {
	363	+	rec := newRecorder()
	364	+	rec.StepStarted(4, "outer", time.Now())
	365	+	j := &job{cfg: Config{Reporter: rec}}
	366	+	j.masker.Store(newMasker())
	367	+	outer := &stepRun{j: j, num: 4}
	368	+	inner := &stepRun{j: j, num: 4, scope: j.embeddedScope(outer, "inner-1")}
	369	+	// the outer step has 8 warnings of its own and the inner one 6: ten are
	370	+	// kept, the outer step's own first
	371	+	for range 8 {
	372	+	j.addIssueFor(outer, issue{Level: LevelWarning, Message: "outer"})
	373	+	}
	374	+	for range 6 {
	375	+	j.addIssueFor(inner, issue{Level: LevelWarning, Message: "inner"})
	376	+	}
	377	+	got := j.collector(4).result()
	378	+	if len(got) != 10 \|\| got[7].Message != "outer" \|\| got[8].Message != "inner" \|\| got[9].Message != "inner" {
	379	+	t.Errorf("%d annotations: %+v", len(got), got)
	380	+	}
	381	+	// summaries of inner steps are appended to the outer step's
	382	+	outer.Summary("# outer\n")
	383	+	inner.Summary("# inner 1\n")
	384	+	inner.Summary("# inner 2\n")
	385	+	if j.summaries[4] != "# outer\n# inner 1\n# inner 2\n" {
	386	+	t.Errorf("%q", j.summaries[4])
	387	+	}
	388	+	// save-state of an inner step goes to the key of its scope
	389	+	inner.SaveState("Key", "v")
	390	+	if g := j.intraActionState("inner-1"); len(g) != 1 \|\| g[0].Key != "Key" {
	391	+	t.Errorf("%v", g)
	392	+	}
	393	+	if g := j.intraActionState("4"); len(g) != 0 {
	394	+	t.Errorf("%v", g)
	395	+	}
	396	+	}
	397	+
	398	+	// Several catastrophic matchers and a step timeout: the step ends at its
	399	+	// timeout, not after every matcher has used its 3 attempts on every line
	400	+	// (GO-004). Without the cancellation of the matchers the 8 matchers x 3
	401	+	// attempts x 1 s of the first line alone hold the step for 24 s.
	402	+	func TestCatastrophicMatchersDoNotHoldAStepPastItsTimeout(t *testing.T) {
	403	+	needTools(t, "bash")
	404	+	var matchers []string
	405	+	var adds []string
	406	+	for i := range 8 {
	407	+	matchers = append(matchers, fmt.Sprintf(`{"owner":"bad%d","pattern":[{"regexp":"^((a+)+)$","message":1}]}`, i))
	408	+	}
	409	+	adds = append(adds, `echo '{"problemMatcher":[`+strings.Join(matchers, ",")+`]}' > bad.json`)
	410	+	start := time.Now()
	411	+	rr, _ := runResults(t, wfHead+` steps:
	412	+	- name: slow lines
	413	+	timeout-minutes: 1
	414	+	run: \|
	415	+	`+adds[0]+`
	416	+	echo "::add-matcher::bad.json"
	417	+	for i in 1 2 3 4 5 6; do echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"; done
	418	+	sleep 30
	419	+	`, func(c Config) { c.StepTimeoutSkew = -(60time.Second - 1500*time.Millisecond) })
	420	+	took := time.Since(start)
	421	+	if took > 8*time.Second {
	422	+	t.Errorf("the step overran its timeout: %v", took)
	423	+	}
	424	+	log := logOf(rr.step(t, "slow lines"))
	425	+	if !strings.Contains(log, "The action 'slow lines' has timed out after 1 minutes.") {
	426	+	t.Errorf("no timeout message:\n%s", log)
	427	+	}
	428	+	// the lines that were not matched are still logged
	429	+	if strings.Count(log, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!") < 6 {
	430	+	t.Errorf("lines lost after the cancellation:\n%s", log)
	431	+	}
	432	+	}

M internal/executor/step.go +15 -4

 	cmdResult *stepResult
 	outcome   *stepResult
 	cmds      *commandManager
+	// scope is what the step shares with the step that contains it, see
+	// stepScope. name is the display name; timedOut is set when the step
+	// reached its timeout-minutes.
+	scope    stepScope
+	name     string
+	timedOut timedOutFlag
 }
 func (s *stepRun) Out(text string)        { s.j.out(s.num, text) }
 	s.j.state.SetOutput(s.st.ID, name, value)
 	s.j.mu.Unlock()
 }
-func (s *stepRun) SaveState(name, value string) {}
 func (s *stepRun) SetEnv(name, value string) {
 	s.j.mu.Lock()
 	s.j.state.SetEnv(name, value)
 		}
 	}
 	name := j.displayName(st, s.env)
+	s.name = name
 	rep.StepStarted(num, name, j.now())
 	complete := func(r stepResult) {
 			outcome = *s.outcome
 		}
 		j.state.SetStepResult(st.ID, string(outcome.conclusion()), string(res.conclusion()))
+		j.recordOutcome(num, outcome.conclusion())
 		if res == resFailed {
 			m := merge(j.result, resFailed)
 			j.result = &m
 	// cancelled and the step is stopped unless its condition still holds
 	// (always()).
 	stepCancel := make(chan struct{})
+	var cancelOnce sync.Once
+	closeCancel := func() { cancelOnce.Do(func() { close(stepCancel) }) }
 	stopWatch := make(chan struct{})
 	var watch sync.WaitGroup
 	if !cancelledAtStart {
 				keep, _ = cond()
 			}
 			if !keep {
-				close(stepCancel)
+				closeCancel()
 			}
 		}()
 	}
+	stopTimeout, minutes := j.armStepTimeout(s, closeCancel)
+	defer stopTimeout()
 	r := j.execute(s, stepCancel)
 	close(stopWatch)
 	watch.Wait()
+	r = j.stepTimedOut(s, r, minutes)
 	// Merge the result of the commands (StepsRunner.cs:347-351).
 	if s.cmdResult != nil {
 	switch {
 	case st.Uses != nil:
 		return fmt.Sprintf("not supported yet: uses (%s)", st.Uses.Value)
-	case st.TimeoutMinutes != nil:
-		return "not supported yet: timeout-minutes"
 	}
 	return ""
 }

M internal/guest/jobexec.go +48 -1


@@ -9,6 +9,7 @@ import (
9		"os/user"	9		"os/user"
10		"strconv"	10		"strconv"
11		"strings"	11		"strings"
			12	+	"sync"
12		"syscall"	13		"syscall"
13		"time"	14		"time"
14			15

@@ -22,6 +23,9 @@ import (
22		// frameReporter is the executor.Reporter that writes frames on the stream.	23		// frameReporter is the executor.Reporter that writes frames on the stream.
23		type frameReporter struct {	24		type frameReporter struct {
24		conn *execstream.Conn	25		conn *execstream.Conn
			26	+	// outcomes keeps steps.<id>.outcome from StepResults until StepCompleted.
			27	+	omu sync.Mutex
			28	+	outcomes map[int]executor.Conclusion
25		// err keeps the first send error; the job goes on without a host.	29		// err keeps the first send error; the job goes on without a host.
26		failed chan struct{}	30		failed chan struct{}
27		}	31		}

@@ -65,7 +69,49 @@ func (r *frameReporter) Log(n int, at time.Time, line string) {
65		}	69		}
66			70
67		func (r *frameReporter) StepCompleted(n int, name string, c executor.Conclusion, at time.Time) {	71		func (r *frameReporter) StepCompleted(n int, name string, c executor.Conclusion, at time.Time) {
68	-	r.send(&execpb.Frame{Body: &execpb.Frame_StepCompleted{StepCompleted: &execpb.StepCompleted{Number: int32(n), Name: name, Conclusion: conclusionProto(c), UnixNano: ts(at)}}})	72	+	r.omu.Lock()
			73	+	outcome := r.outcomes[n]
			74	+	delete(r.outcomes, n)
			75	+	r.omu.Unlock()
			76	+	r.send(&execpb.Frame{Body: &execpb.Frame_StepCompleted{StepCompleted: &execpb.StepCompleted{
			77	+	Number: int32(n), Name: name, Conclusion: conclusionProto(c), Outcome: conclusionProto(outcome), UnixNano: ts(at),
			78	+	}}})
			79	+	}
			80	+
			81	+	func levelProto(l executor.AnnotationLevel) execpb.AnnotationLevel {
			82	+	switch l {
			83	+	case executor.LevelNotice:
			84	+	return execpb.AnnotationLevel_ANNOTATION_LEVEL_NOTICE
			85	+	case executor.LevelWarning:
			86	+	return execpb.AnnotationLevel_ANNOTATION_LEVEL_WARNING
			87	+	case executor.LevelFailure:
			88	+	return execpb.AnnotationLevel_ANNOTATION_LEVEL_FAILURE
			89	+	}
			90	+	return execpb.AnnotationLevel_ANNOTATION_LEVEL_UNSPECIFIED
			91	+	}
			92	+
			93	+	// StepResults sends the annotations and the summary of a step, and keeps its
			94	+	// outcome for the StepCompleted frame that follows.
			95	+	func (r *frameReporter) StepResults(n int, res executor.StepResults) {
			96	+	r.omu.Lock()
			97	+	if r.outcomes == nil {
			98	+	r.outcomes = map[int]executor.Conclusion{}
			99	+	}
			100	+	r.outcomes[n] = res.Outcome
			101	+	r.omu.Unlock()
			102	+	if len(res.Annotations) > 0 {
			103	+	sa := &execpb.StepAnnotations{Step: int32(n)}
			104	+	for _, a := range res.Annotations {
			105	+	sa.Annotations = append(sa.Annotations, &execpb.Annotation{
			106	+	Level: levelProto(a.Level), Title: a.Title, Message: a.Message, File: a.File,
			107	+	StartLine: a.StartLine, EndLine: a.EndLine, StartColumn: a.StartColumn, EndColumn: a.EndColumn,
			108	+	})
			109	+	}
			110	+	r.send(&execpb.Frame{Body: &execpb.Frame_StepAnnotations{StepAnnotations: sa}})
			111	+	}
			112	+	if res.HasSummary {
			113	+	r.send(&execpb.Frame{Body: &execpb.Frame_StepSummary{StepSummary: &execpb.StepSummary{Step: int32(n), Markdown: res.Summary}}})
			114	+	}
69		}	115		}
70			116
71		func (r *frameReporter) JobCompleted(res executor.Result) {	117		func (r *frameReporter) JobCompleted(res executor.Result) {

@@ -207,6 +253,7 @@ func runJob(ctx context.Context, conn execstream.Conn, cfg ExecConfig, spec ex
207		RunnerVersion: spec.GetRunnerVersion(),	253		RunnerVersion: spec.GetRunnerVersion(),
208		Home: su.Home, ToolCache: os.Getenv("RUNNER_TOOL_CACHE"), BaseEnv: stepEnv(os.Environ(), su), Credential: su.Credential,	254		Home: su.Home, ToolCache: os.Getenv("RUNNER_TOOL_CACHE"), BaseEnv: stepEnv(os.Environ(), su), Credential: su.Credential,
209		Debug: spec.GetDebug(), Reporter: rep, Log: zerowrap.FromCtx(ctx),	255		Debug: spec.GetDebug(), Reporter: rep, Log: zerowrap.FromCtx(ctx),
			256	+	SendAnnotations: spec.GetSendAnnotations(), SendSummaries: spec.GetSendSummaries(),
210		TermAfter: cfg.TermAfter, KillAfter: cfg.KillAfter, WaitDelay: cfg.WaitDelay,	257		TermAfter: cfg.TermAfter, KillAfter: cfg.KillAfter, WaitDelay: cfg.WaitDelay,
211		})	258		})
212		if res.Conclusion == executor.ConclusionSuccess {	259		if res.Conclusion == executor.ConclusionSuccess {

M internal/guest/jobexec_test.go +74 -0


@@ -257,3 +257,77 @@ func TestFailSetupReportsAFailedFirstStep(t *testing.T) {
257	t.Fatalf("%s", g)	257		t.Fatalf("%s", g)
258	}	258		}
259	}	259		}
		260	+
		261	+	// The executor over the stream: annotations, summary and outcome frames
		262	+	// arrive before the StepCompleted of their step, only when the host asked.
		263	+	func TestExecSendsResultsFrames(t *testing.T) {
		264	+	requireBash(t)
		265	+	yaml := "on: push\njobs:\n j:\n runs-on: x\n steps:\n - run: \|\n echo '::warning title=T::careful'\n echo '# sum' >> \"$GITHUB_STEP_SUMMARY\"\n exit 1\n continue-on-error: true\n"
		266	+	for _, on := range []bool{true, false} {
		267	+	sock := filepath.Join(t.TempDir(), "s")
		268	+	ln, err := net.Listen("unix", sock)
		269	+	if err != nil {
		270	+	t.Skip(err)
		271	+	}
		272	+	home := t.TempDir()
		273	+	t.Setenv("HOME", home)
		274	+	t.Setenv("RUNNER_TOOL_CACHE", filepath.Join(home, "toolcache"))
		275	+	done := make(chan struct{})
		276	+	go func() {
		277	+	defer close(done)
		278	+	_, _ = Exec(context.Background(), ExecConfig{Target: Target{"unix", sock}, Sandbox: "container", Version: "test", RunTimeout: 5 * time.Second,
		279	+	TermAfter: 200 * time.Millisecond, KillAfter: 200 * time.Millisecond, WaitDelay: 300 * time.Millisecond})
		280	+	}()
		281	+	conn, err := ln.Accept()
		282	+	if err != nil {
		283	+	t.Fatal(err)
		284	+	}
		285	+	var order []string
		286	+	var anns *execpb.StepAnnotations
		287	+	var sum *execpb.StepSummary
		288	+	var done2 *execpb.StepCompleted
		289	+	_, _, err = execstream.DriveJob(conn, &execpb.Run{Job: &execpb.JobSpec{
		290	+	WorkflowPath: ".github/workflows/ci.yml", WorkflowYaml: yaml, JobKey: "j", Repo: "hello", RunnerName: "r", RunnerVersion: "v",
		291	+	Contexts: `{"github":{"repository":"octo/hello","event_name":"push","job":"j"}}`, Matrix: "{}",
		292	+	SendAnnotations: on, SendSummaries: on,
		293	+	}}, nil, execstream.JobHandler{
		294	+	StepAnnotations: func(a *execpb.StepAnnotations) { order = append(order, "ann"); anns = a },
		295	+	StepSummary: func(s *execpb.StepSummary) { order = append(order, "sum"); sum = s },
		296	+	StepCompleted: func(s *execpb.StepCompleted) {
		297	+	if s.Number == 2 {
		298	+	order = append(order, "done")
		299	+	done2 = s
		300	+	}
		301	+	},
		302	+	})
		303	+	_ = conn.Close()
		304	+	_ = ln.Close()
		305	+	<-done
		306	+	if err != nil {
		307	+	t.Fatal(err)
		308	+	}
		309	+	if done2 == nil \|\| done2.Conclusion != execpb.StepConclusion_STEP_CONCLUSION_SUCCESS \|\| done2.Outcome != execpb.StepConclusion_STEP_CONCLUSION_FAILURE {
		310	+	t.Fatalf("on=%v: %+v", on, done2)
		311	+	}
		312	+	if !on {
		313	+	if len(order) != 1 {
		314	+	t.Errorf("frames without the features: %v", order)
		315	+	}
		316	+	continue
		317	+	}
		318	+	if strings.Join(order, ",") != "ann,sum,done" {
		319	+	t.Errorf("order %v", order)
		320	+	}
		321	+	// the failing exit code is also an annotation
		322	+	var msgs []string
		323	+	for _, a := range anns.Annotations {
		324	+	msgs = append(msgs, a.Level.String()+":"+a.Title+":"+a.Message)
		325	+	}
		326	+	if anns.Step != 2 \|\| len(msgs) != 2 \|\| msgs[0] != "ANNOTATION_LEVEL_WARNING:T:careful" \|\| msgs[1] != "ANNOTATION_LEVEL_FAILURE::Process completed with exit code 1." {
		327	+	t.Errorf("annotations %v", msgs)
		328	+	}
		329	+	if sum == nil \|\| sum.Step != 2 \|\| sum.Markdown != "# sum\n" {
		330	+	t.Errorf("summary %+v", sum)
		331	+	}
		332	+	}
		333	+	}

M internal/host/fake_test.go +60 -13


@@ -44,14 +44,19 @@ type fakeServer struct {
44		beatHook func(n int) error	44		beatHook func(n int) error
45		registers []*ermite.RegisterRunnerRequest	45		registers []*ermite.RegisterRunnerRequest
46			46
47	-	store *hosttest.LogStore	47	+	store *hosttest.LogStore
48	-	violations []string	48	+	violations []string
49	-	lines []string // log text, one per line (mirror of store)	49	+	lines []string // log text, one per line (mirror of store)
50	-	cont []bool	50	+	cont []bool
51	-	steps map[int32]*ermite.StepUpdate	51	+	steps map[int32]*ermite.StepUpdate
52	-	appendReq []*ermite.AppendLogRequest	52	+	annots map[int32][]*ermite.Annotation // by step, replaced by each call that names the step
53	-	appendHook func(n int, req *ermite.AppendLogRequest) (applyThenFail bool, err error)	53	+	summaries map[int32]string
54	-	appendN int	54	+	updates []*ermite.UpdateJobRequest
			55	+	updateHook func(n int, req *ermite.UpdateJobRequest) error
			56	+	summaryHook func(req *ermite.UploadSummaryRequest) error
			57	+	appendReq []*ermite.AppendLogRequest
			58	+	appendHook func(n int, req *ermite.AppendLogRequest) (applyThenFail bool, err error)
			59	+	appendN int
55			60
56		completes []*ermite.CompleteJobRequest	61		completes []*ermite.CompleteJobRequest
57		completeHook func(n int) (applyThenFail bool, err error)	62		completeHook func(n int) (applyThenFail bool, err error)

@@ -170,12 +175,52 @@ func (s fakeServer) UpdateJob(_ context.Context, r connect.Request[ermite.Upda
170		}	175		}
171		return nil, endedErr(je)	176		return nil, endedErr(je)
172		}	177		}
			178	+	s.updates = append(s.updates, r.Msg)
			179	+	if s.updateHook != nil {
			180	+	if err := s.updateHook(len(s.updates), r.Msg); err != nil {
			181	+	return nil, err
			182	+	}
			183	+	}
173		for _, u := range r.Msg.Steps {	184		for _, u := range r.Msg.Steps {
174		s.steps[u.Number] = u	185		s.steps[u.Number] = u
175		}	186		}
			187	+	s.replaceAnnotations(r.Msg.Annotations)
176		return connect.NewResponse(&ermite.UpdateJobResponse{}), nil	188		return connect.NewResponse(&ermite.UpdateJobResponse{}), nil
177		}	189		}
178			190
			191	+	// replaceAnnotations applies the replace-per-step rule of runner.proto.
			192	+	func (s fakeServer) replaceAnnotations(anns []ermite.Annotation) {
			193	+	if s.annots == nil {
			194	+	s.annots = map[int32][]*ermite.Annotation{}
			195	+	}
			196	+	named := map[int32]bool{}
			197	+	for _, a := range anns {
			198	+	if !named[a.StepNumber] {
			199	+	named[a.StepNumber] = true
			200	+	s.annots[a.StepNumber] = nil
			201	+	}
			202	+	s.annots[a.StepNumber] = append(s.annots[a.StepNumber], a)
			203	+	}
			204	+	}
			205	+
			206	+	func (s fakeServer) UploadSummary(_ context.Context, r connect.Request[ermite.UploadSummaryRequest]) (*connect.Response[ermite.UploadSummaryResponse], error) {
			207	+	s.mu.Lock()
			208	+	defer s.mu.Unlock()
			209	+	if _, err := s.checkJob(r.Header(), r.Msg.JobId); err != nil {
			210	+	return nil, err
			211	+	}
			212	+	if s.summaryHook != nil {
			213	+	if err := s.summaryHook(r.Msg); err != nil {
			214	+	return nil, err
			215	+	}
			216	+	}
			217	+	if s.summaries == nil {
			218	+	s.summaries = map[int32]string{}
			219	+	}
			220	+	s.summaries[r.Msg.StepNumber] = r.Msg.Markdown
			221	+	return connect.NewResponse(&ermite.UploadSummaryResponse{}), nil
			222	+	}
			223	+
179		func (s fakeServer) AppendLog(_ context.Context, r connect.Request[ermite.AppendLogRequest]) (*connect.Response[ermite.AppendLogResponse], error) {	224		func (s fakeServer) AppendLog(_ context.Context, r connect.Request[ermite.AppendLogRequest]) (*connect.Response[ermite.AppendLogResponse], error) {
180		s.mu.Lock()	225		s.mu.Lock()
181		defer s.mu.Unlock()	226		defer s.mu.Unlock()

@@ -223,6 +268,7 @@ func (s fakeServer) CompleteJob(_ context.Context, r connect.Request[ermite.Co
223		}	268		}
224		s.completeN++	269		s.completeN++
225		s.completes = append(s.completes, r.Msg)	270		s.completes = append(s.completes, r.Msg)
			271	+	s.replaceAnnotations(r.Msg.Annotations)
226		if s.completeHook != nil {	272		if s.completeHook != nil {
227		thenFail, err := s.completeHook(s.completeN)	273		thenFail, err := s.completeHook(s.completeN)
228		if err != nil {	274		if err != nil {

@@ -507,11 +553,12 @@ func newHarness(t testing.T, sc script) harness {
507		}	553		}
508		})	554		})
509		h.runner = &Runner{	555		h.runner = &Runner{
510	-	Cfg: Config{URL: url, Name: "r1", Capacity: 1, Version: "test"},	556	+	Cfg: Config{URL: url, Name: "r1", Capacity: 1, Version: "test"},
511	-	Driver: drv,	557	+	Driver: drv,
512	-	Poll: NewClient(url, "ermiterun_tok", http.DefaultTransport),	558	+	Poll: NewClient(url, "ermiterun_tok", http.DefaultTransport),
513	-	Job: func(tok string) ermiteconnect.RunnerServiceClient { return NewClient(url, tok, http.DefaultTransport) },	559	+	Features: func(context.Context) ([]string, error) { return []string{FeatureAnnotations, FeatureSummaries}, nil },
514	-	Timing: fastTiming(),	560	+	Job: func(tok string) ermiteconnect.RunnerServiceClient { return NewClient(url, tok, http.DefaultTransport) },
			561	+	Timing: fastTiming(),
515		}	562		}
516		return h	563		return h
517		}	564		}

M internal/host/hosttest/hosttest.go +49 -5

 // Result is what a job reported.
 type Result struct {
-	Complete *ermite.CompleteJobRequest
+	// Annotations are those stored, by step (replace-per-step rule), and
-	Lines    []Line
+	// Summaries the Markdown stored by step.
-	Steps    map[int32]*ermite.StepUpdate
+	Annotations map[int32][]*ermite.Annotation
+	Summaries   map[int32]string
+	Complete    *ermite.CompleteJobRequest
+	Lines       []Line
+	Steps       map[int32]*ermite.StepUpdate
 }
 // Server is the fake. Create it with New; URL is where to point the runner.
 }
 type jobState struct {
+	annots   map[int32][]*ermite.Annotation
+	sums     map[int32]string
 	log      *LogStore
 	steps    map[int32]*ermite.StepUpdate
 	complete *ermite.CompleteJobRequest
 	for k, v := range st.steps {
 		steps[k] = v
 	}
-	return Result{Complete: st.complete, Lines: st.log.Lines(), Steps: steps}
+	anns := map[int32][]*ermite.Annotation{}
+	for k, v := range st.annots {
+		anns[k] = v
+	}
+	sums := map[int32]string{}
+	for k, v := range st.sums {
+		sums[k] = v
+	}
+	return Result{Complete: st.complete, Lines: st.log.Lines(), Steps: steps, Annotations: anns, Summaries: sums}
 }
 func (s *Server) violation(msg string) { s.Errors = append(s.Errors, msg) } // called with s.mu held
 	j := s.queue[0]
 	s.queue = s.queue[1:]
 	s.assigned[j.JobToken] = j
-	s.jobs[j.JobId] = &jobState{log: &LogStore{OnViolation: s.violation}, steps: map[int32]*ermite.StepUpdate{}}
+	s.jobs[j.JobId] = &jobState{log: &LogStore{OnViolation: s.violation}, steps: map[int32]*ermite.StepUpdate{}, annots: map[int32][]*ermite.Annotation{}, sums: map[int32]string{}}
 	return connect.NewResponse(&ermite.FetchJobResponse{Job: j}), nil
 }
 		}
 		st.steps[u.Number] = u
 	}
+	replace(st.annots, r.Msg.Annotations)
 	return connect.NewResponse(&ermite.UpdateJobResponse{}), nil
 }
 	for _, u := range r.Msg.Steps {
 		st.steps[u.Number] = u
 	}
+	replace(st.annots, r.Msg.Annotations)
 	s.done <- r.Msg.JobId
 	return connect.NewResponse(&ermite.CompleteJobResponse{Conclusion: r.Msg.Conclusion, Applied: true}), nil
 }
 	<-ctx.Done()
 	return ctx.Err()
 }
+// replace applies the rule of runner.proto: the annotations of each step the
+// call names replace those stored.
+func replace(stored map[int32][]*ermite.Annotation, anns []*ermite.Annotation) {
+	named := map[int32]bool{}
+	for _, a := range anns {
+		if !named[a.StepNumber] {
+			named[a.StepNumber] = true
+			stored[a.StepNumber] = nil
+		}
+		stored[a.StepNumber] = append(stored[a.StepNumber], a)
+	}
+}
+// UploadSummary stores the summary of a step.
+func (s *Server) UploadSummary(_ context.Context, r *connect.Request[ermite.UploadSummaryRequest]) (*connect.Response[ermite.UploadSummaryResponse], error) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	st, err := s.job(r.Header(), r.Msg.JobId)
+	if err != nil {
+		return nil, err
+	}
+	if st.complete != nil {
+		return nil, ended(st.complete.Conclusion)
+	}
+	st.sums[r.Msg.StepNumber] = r.Msg.Markdown
+	return connect.NewResponse(&ermite.UploadSummaryResponse{}), nil
+}

M internal/host/job.go +52 -7

 	// contexts is Job.Contexts as handed to the executor: with the server URLs
 	// pointed at the runner's URL when guest forge access is on.
 	contexts string
+	// features is what the server accepts; annLists are the annotations the
+	// executor sent for steps that have not completed yet (see results.go).
+	features jobFeatures
+	annLists map[int32][]*ermite.Annotation
+	// annSeen and sumSeen are the steps that sent their annotations and their
+	// summary: each is sent once.
+	annSeen, sumSeen map[int32]bool
+	annDropped       int // annotations dropped for lack of room, see reportDroppedAnnotations
 	// hard stops the sandbox at once; set before the session starts.
 	hard    func()
 	result  *execpb.JobResult
 	u := &ermite.StepUpdate{Number: s.Number, Name: cutName(s.Name), State: ermite.StepState_STEP_STATE_IN_PROGRESS, StartedAt: tsOf(s.UnixNano)}
 	j.steps[s.Number] = u
 	j.mu.Unlock()
-	j.outbox.Step(u)
+	j.outbox.Step(u, nil)
 }
 func (j *jobRun) stepCompleted(s *execpb.StepCompleted) {
 		u.Conclusion = ermite.CiConclusion_CI_CONCLUSION_FAILURE
 	}
 	u.CompletedAt = tsOf(s.UnixNano)
+	// The outcome is how the step ended before continue-on-error; a runner that
+	// does not say leaves it unspecified, which means the conclusion.
+	if o := conclusionOf(s.Outcome); o != ermite.CiConclusion_CI_CONCLUSION_UNSPECIFIED {
+		if o == ermite.CiConclusion_CI_CONCLUSION_TIMED_OUT {
+			o = ermite.CiConclusion_CI_CONCLUSION_FAILURE
+		}
+		u.Outcome = o
+	}
 	j.steps[s.Number] = u
+	anns := j.takeAnnotations(s.Number)
 	j.mu.Unlock()
-	j.outbox.Step(u)
+	j.outbox.Step(u, anns)
 }
 // logLine checks and queues a line of the log. The step must be one that was
 }
 // cutName bounds a step name to what the server keeps, on a character boundary.
+// The result is a copy: a substring would keep the whole name the guest sent
+// alive (see cutRunes).
 func cutName(s string) string {
 	if len(s) <= maxNameLen {
 		return strings.ToValidUTF8(s, "\ufffd")
 	for !utf8.ValidString(s) && len(s) > 0 {
 		s = s[:len(s)-1]
 	}
-	return s
+	return strings.Clone(s)
 }
 func cloneStep(u *ermite.StepUpdate) *ermite.StepUpdate {
 	j.outbox.start(ctx)
 	stopHard := j.startStopTimers(ctx, shutdown)
+	// The hard stop frees the reader of the stream if it waits for room in the
+	// outbox (the server keeps failing): nothing else would wake it.
+	go func() {
+		select {
+		case <-stopHard:
+			j.outbox.releaseProducers()
+		case <-ctx.Done():
+		}
+	}()
 	out := j.execute(ctx, rt, stopHard)
 	j.report(ctx, out, shutdown)
 }
 		j.sandboxError(msg)
 		out = failure()
 	}
-	j.outbox.Close(rctx)
+	// The flush gets half of the budget: when the server keeps failing the
+	// uploads, the other half is still there for CompleteJob, which is what
+	// ends the job for the server.
+	fctx, fcancel := context.WithTimeout(rctx, budget/2)
+	j.outbox.Close(fctx)
+	fcancel()
 	if err := j.abandoned(); err != nil {
 		return
 	}
+	j.reportDroppedAnnotations(rctx, budget/4)
 	j.complete(rctx, out.conclusion, out.outputs, out.shutdown)
 }
 	}
 	// Stop runs to completion even when the job context is done.
 	defer j.stopSandbox(ctx, rt, sb)
+	j.features = j.loadFeatures(ctx, rt)
 	conn, err := j.startSandbox(ctx, rt, sb, stopHard)
 	if err != nil {
 		Matrix: j.job.Matrix, Contexts: j.contexts, Repo: j.job.Repo, TimeoutMinutes: int32(j.timeoutMinutes()),
 		DeadlineMs: max(1, time.Until(j.deadline()).Milliseconds()),
 		RunnerName: rt.Cfg.Name, RunnerVersion: rt.Cfg.Version, RunnerEnvironment: rt.Cfg.environment(),
+		SendAnnotations: j.features.annotations, SendSummaries: j.features.summaries,
 	}}
 	_, exit, err := execstream.DriveJob(conn, run, j.cancelCh, execstream.JobHandler{
 		StepStarted: j.stepStarted, StepCompleted: j.stepCompleted,
-		Log:       j.logLine,
+		Log:             j.logLine,
-		JobResult: func(r *execpb.JobResult) { j.mu.Lock(); j.result = r; j.mu.Unlock() },
+		JobResult:       func(r *execpb.JobResult) { j.mu.Lock(); j.result = r; j.mu.Unlock() },
+		StepAnnotations: j.stepAnnotations, StepSummary: j.stepSummary,
 	})
 	return exit, err
 }
 		JobId: j.job.JobId, Conclusion: conclusion, Outputs: outputs,
 		RunnerShutdown: shutdown && conclusion == ermite.CiConclusion_CI_CONCLUSION_CANCELLED,
 		Steps:          j.finalSteps(conclusion),
+		// The annotations no UpdateJob has carried: all of them with the
+		// step they belong to, whole lists (replace semantics).
+		Annotations: j.allPendingAnnotations(),
 	}
 	err := j.sendComplete(ctx, req, conclusion)
 	if err == nil || ctx.Err() != nil || classify(err) != kindPermanent {
 // errorLog appends a line to the log after the outbox is closed.
 func (j *jobRun) errorLog(ctx context.Context, msg string) {
+	j.appendLogLine(ctx, "##[error]"+msg)
+}
+// appendLogLine appends one line, in the last step, after the outbox is closed.
+func (j *jobRun) appendLogLine(ctx context.Context, text string) {
 	j.mu.Lock()
 	var last int32 = 1
 	for n := range j.steps {
 		last = max(last, n)
 	}
 	j.mu.Unlock()
-	j.outbox.AppendNow(ctx, logLine{step: last, unixNano: time.Now().UnixNano(), text: "##[error]" + msg})
+	j.outbox.AppendNow(ctx, logLine{step: last, unixNano: time.Now().UnixNano(), text: text})
 }
 // rebuiltSteps returns every known step as a valid, completed snapshot: number

M internal/host/outbox.go +195 -20


@@ -4,6 +4,7 @@ package host
4			4
5		import (	5		import (
6		"context"	6		"context"
			7	+	"sort"
7		"sync"	8		"sync"
8		"time"	9		"time"
9			10

@@ -37,6 +38,17 @@ type logLine struct {
37		type event struct {	38		type event struct {
38		line *logLine	39		line *logLine
39		step *ermite.StepUpdate	40		step *ermite.StepUpdate
			41	+	// anns are the annotations that go with a step snapshot, by step number:
			42	+	// the whole list of each step they name (replace semantics).
			43	+	anns map[int32][]*ermite.Annotation
			44	+	// summary is a step summary for UploadSummary.
			45	+	summary *summary
			46	+	}
			47	+
			48	+	// summary is the Markdown of one step.
			49	+	type summary struct {
			50	+	step int32
			51	+	markdown string
40		}	52		}
41			53
42		// outbox sends logs and step updates of one job to ermite, in order, one call	54		// outbox sends logs and step updates of one job to ermite, in order, one call

@@ -53,13 +65,30 @@ type outbox struct {
53		onEnded func(error)	65		onEnded func(error)
54		log zerowrap.Logger	66		log zerowrap.Logger
55			67
56	-	mu sync.Mutex	68	+	mu sync.Mutex
57	-	cond *sync.Cond	69	+	cond *sync.Cond
58	-	events []event	70	+	events []event
59	-	queued int // bytes of log text in events	71	+	// queued is the memory the outbox holds for the server, in bytes: log text
			72	+	// and summaries in events, and annotations from the moment the host
			73	+	// received them until the call that carries them is answered. One budget,
			74	+	// maxQueuedBytes, for all of it.
			75	+	queued int
60		closing bool	76		closing bool
61		dead bool	77		dead bool
62	-	done chan struct{}	78	+	// released is set by the hard stop of the job (releaseProducers): the
			79	+	// producers that wait for room stop waiting and drop what they hold, and
			80	+	// what is offered over the budget is dropped instead of waited for.
			81	+	released bool
			82	+	// stopSender ends the context the sender works with (start): kill calls
			83	+	// it, so that a call or a retry delay in progress ends with the outbox and
			84	+	// Close can wait for the sender after giving up.
			85	+	stopSender context.CancelFunc
			86	+	done chan struct{}
			87	+
			88	+	// pendingAnns are the annotations the server may not hold yet, by step: the
			89	+	// last list queued for the step, until an UpdateJob that carried it
			90	+	// succeeded. CompleteJob sends what is left.
			91	+	pendingAnns map[int32][]*ermite.Annotation
63			92
64		offset int64 // lines the server holds, as far as we know	93		offset int64 // lines the server holds, as far as we know
65		// offsetMaybeStale is set when a send was cut short by its context while	94		// offsetMaybeStale is set when a send was cut short by its context while

@@ -71,6 +100,7 @@ type outbox struct {
71		// callClient is the part of the RunnerService client the job uses.	100		// callClient is the part of the RunnerService client the job uses.
72		type callClient interface {	101		type callClient interface {
73		UpdateJob(context.Context, connect.Request[ermite.UpdateJobRequest]) (connect.Response[ermite.UpdateJobResponse], error)	102		UpdateJob(context.Context, connect.Request[ermite.UpdateJobRequest]) (connect.Response[ermite.UpdateJobResponse], error)
			103	+	UploadSummary(context.Context, connect.Request[ermite.UploadSummaryRequest]) (connect.Response[ermite.UploadSummaryResponse], error)
74		AppendLog(context.Context, connect.Request[ermite.AppendLogRequest]) (connect.Response[ermite.AppendLogResponse], error)	104		AppendLog(context.Context, connect.Request[ermite.AppendLogRequest]) (connect.Response[ermite.AppendLogResponse], error)
75		}	105		}
76			106

@@ -82,9 +112,14 @@ func newOutbox(c callClient, jobID string, t Timing, onEnded func(error), log ze
82			112
83		// start runs the sender until Close or until ctx ends.	113		// start runs the sender until Close or until ctx ends.
84		func (o *outbox) start(ctx context.Context) {	114		func (o *outbox) start(ctx context.Context) {
			115	+	sctx, stop := context.WithCancel(ctx)
			116	+	o.mu.Lock()
			117	+	o.stopSender = stop
			118	+	o.mu.Unlock()
85		go func() {	119		go func() {
86		defer close(o.done)	120		defer close(o.done)
87	-	o.loop(ctx)	121	+	defer stop()
			122	+	o.loop(sctx)
88		}()	123		}()
89		// A cancelled context must wake the loop and the producers.	124		// A cancelled context must wake the loop and the producers.
90		go func() {	125		go func() {

@@ -101,17 +136,44 @@ func (o *outbox) kill() {
101		o.dead = true	136		o.dead = true
102		o.events = nil	137		o.events = nil
103		o.queued = 0	138		o.queued = 0
			139	+	stop := o.stopSender
104		o.mu.Unlock()	140		o.mu.Unlock()
			141	+	if stop != nil {
			142	+	stop()
			143	+	}
105		o.cond.Broadcast()	144		o.cond.Broadcast()
106		}	145		}
107			146
108	-	// Log queues a line of the job log. It blocks while too much is queued.	147	+	// waitRoomLocked blocks while too much is queued. It returns false when the
109	-	func (o *outbox) Log(l logLine) {	148	+	// item must be dropped: the outbox is dead, or the hard stop released the
110	-	o.mu.Lock()	149	+	// producers and there is still no room. Closing lets the last items in.
111	-	for o.queued > maxQueuedBytes && !o.dead && !o.closing {	150	+	func (o *outbox) waitRoomLocked() bool {
			151	+	for o.queued > maxQueuedBytes && !o.dead && !o.closing && !o.released {
112		o.cond.Wait()	152		o.cond.Wait()
113		}	153		}
114		if o.dead {	154		if o.dead {
			155	+	return false
			156	+	}
			157	+	return o.queued <= maxQueuedBytes \|\| o.closing
			158	+	}
			159	+
			160	+	// releaseProducers wakes the producers that wait for room and makes them (and
			161	+	// the ones that come) drop their items when there is none: called by the hard
			162	+	// stop of the job, because the sender may never make room (the server keeps
			163	+	// failing) and the producer is the reader of the stream of the sandbox. What
			164	+	// is queued is still sent by Close, within its budget.
			165	+	func (o *outbox) releaseProducers() {
			166	+	o.mu.Lock()
			167	+	o.released = true
			168	+	o.mu.Unlock()
			169	+	o.cond.Broadcast()
			170	+	}
			171	+
			172	+	// Log queues a line of the job log. It blocks while too much is queued, until
			173	+	// the hard stop of the job releases it.
			174	+	func (o *outbox) Log(l logLine) {
			175	+	o.mu.Lock()
			176	+	if !o.waitRoomLocked() {
115		o.mu.Unlock()	177		o.mu.Unlock()
116		return	178		return
117		}	179		}

@@ -121,18 +183,86 @@ func (o *outbox) Log(l logLine) {
121		o.cond.Broadcast()	183		o.cond.Broadcast()
122		}	184		}
123			185
124	-	// Step queues a step snapshot.	186	+	// ReserveAnnotations counts the bytes of a list of annotations in the budget,
125	-	func (o outbox) Step(s ermite.StepUpdate) {	187	+	// from the moment the host holds it. It returns false, and counts nothing,
			188	+	// when there is no room: the caller drops the list (annotations are not worth
			189	+	// stopping the reader of the stream for: it also carries the frames that
			190	+	// complete the steps and free the room).
			191	+	func (o *outbox) ReserveAnnotations(n int) bool {
			192	+	o.mu.Lock()
			193	+	defer o.mu.Unlock()
			194	+	if o.dead \|\| o.queued+n > maxQueuedBytes {
			195	+	return false
			196	+	}
			197	+	o.queued += n
			198	+	return true
			199	+	}
			200	+
			201	+	// releaseAnnotations gives the bytes back once the call that carried the
			202	+	// lists was answered (or refused).
			203	+	func (o *outbox) releaseAnnotations(n int) {
			204	+	o.mu.Lock()
			205	+	if !o.dead {
			206	+	o.queued -= n
			207	+	}
			208	+	o.mu.Unlock()
			209	+	o.cond.Broadcast()
			210	+	}
			211	+
			212	+	// Step queues a step snapshot, with the annotations that changed (may be nil).
			213	+	func (o outbox) Step(s ermite.StepUpdate, anns map[int32][]*ermite.Annotation) {
126		o.mu.Lock()	214		o.mu.Lock()
127		if o.dead {	215		if o.dead {
128		o.mu.Unlock()	216		o.mu.Unlock()
129		return	217		return
130		}	218		}
131	-	o.events = append(o.events, event{step: s})	219	+	for n, l := range anns {
			220	+	if o.pendingAnns == nil {
			221	+	o.pendingAnns = map[int32][]*ermite.Annotation{}
			222	+	}
			223	+	o.pendingAnns[n] = l
			224	+	}
			225	+	o.events = append(o.events, event{step: s, anns: anns})
132		o.mu.Unlock()	226		o.mu.Unlock()
133		o.cond.Broadcast()	227		o.cond.Broadcast()
134		}	228		}
135			229
			230	+	// Summary queues the summary of a step. Its bytes count with the log text in
			231	+	// the bounded memory of the outbox: it blocks while too much is queued, until
			232	+	// the hard stop of the job releases it.
			233	+	func (o *outbox) Summary(step int32, markdown string) {
			234	+	o.mu.Lock()
			235	+	if !o.waitRoomLocked() {
			236	+	o.mu.Unlock()
			237	+	return
			238	+	}
			239	+	o.events = append(o.events, event{summary: &summary{step, markdown}})
			240	+	o.queued += len(markdown) + 32
			241	+	o.mu.Unlock()
			242	+	o.cond.Broadcast()
			243	+	}
			244	+
			245	+	// PendingAnnotations returns the annotations that no successful UpdateJob has
			246	+	// carried, for CompleteJob, in step order.
			247	+	func (o outbox) PendingAnnotations() []ermite.Annotation {
			248	+	o.mu.Lock()
			249	+	defer o.mu.Unlock()
			250	+	return flattenAnnotations(o.pendingAnns)
			251	+	}
			252	+
			253	+	func flattenAnnotations(m map[int32][]ermite.Annotation) []ermite.Annotation {
			254	+	steps := make([]int32, 0, len(m))
			255	+	for n := range m {
			256	+	steps = append(steps, n)
			257	+	}
			258	+	sort.Slice(steps, func(a, b int) bool { return steps[a] < steps[b] })
			259	+	var out []*ermite.Annotation
			260	+	for _, n := range steps {
			261	+	out = append(out, m[n]...)
			262	+	}
			263	+	return out
			264	+	}
			265	+
136		// Close sends what is queued, then stops the sender. It waits at most until	266		// Close sends what is queued, then stops the sender. It waits at most until
137		// ctx ends.	267		// ctx ends.
138		func (o *outbox) Close(ctx context.Context) {	268		func (o *outbox) Close(ctx context.Context) {

@@ -179,8 +309,12 @@ func (o *outbox) next(ctx context.Context) []event {
179		return nil	309		return nil
180		}	310		}
181		first := o.events[0]	311		first := o.events[0]
182	-	if first.step != nil {	312	+	if first.step != nil \|\| first.summary != nil {
183		o.events = o.events[1:]	313		o.events = o.events[1:]
			314	+	if first.summary != nil {
			315	+	o.queued -= len(first.summary.markdown) + 32
			316	+	o.cond.Broadcast() // producers waiting for room
			317	+	}
184		return []event{first}	318		return []event{first}
185		}	319		}
186		// A run of lines of the same step, within the limits.	320		// A run of lines of the same step, within the limits.

@@ -208,9 +342,12 @@ func (o *outbox) loop(ctx context.Context) {
208		if batch == nil {	342		if batch == nil {
209		return	343		return
210		}	344		}
211	-	if batch[0].step != nil {	345	+	switch {
212	-	o.sendStep(ctx, batch[0].step)	346	+	case batch[0].step != nil:
213	-	} else {	347	+	o.sendStep(ctx, batch[0].step, batch[0].anns)
			348	+	case batch[0].summary != nil:
			349	+	o.sendSummary(ctx, batch[0].summary)
			350	+	default:
214		o.sendLines(ctx, batch)	351		o.sendLines(ctx, batch)
215		}	352		}
216		o.mu.Lock()	353		o.mu.Lock()

@@ -251,13 +388,51 @@ func (o *outbox) retry(ctx context.Context, what string, call func(context.Conte
251		}	388		}
252		}	389		}
253			390
254	-	func (o outbox) sendStep(ctx context.Context, s ermite.StepUpdate) {	391	+	func (o outbox) sendStep(ctx context.Context, s ermite.StepUpdate, anns map[int32][]*ermite.Annotation) {
			392	+	req := &ermite.UpdateJobRequest{JobId: o.jobID, Steps: []*ermite.StepUpdate{s}, Annotations: flattenAnnotations(anns)}
255		err := o.retry(ctx, "UpdateJob", func(c context.Context) error {	393		err := o.retry(ctx, "UpdateJob", func(c context.Context) error {
256	-	_, err := o.client.UpdateJob(c, connect.NewRequest(&ermite.UpdateJobRequest{JobId: o.jobID, Steps: []*ermite.StepUpdate{s}}))	394	+	_, err := o.client.UpdateJob(c, connect.NewRequest(req))
257		return err	395		return err
258		})	396		})
259	-	if err != nil && ctx.Err() == nil && classify(err) == kindPermanent {	397	+	if err == nil {
			398	+	// The server holds these lists now: they leave the pending ones and
			399	+	// the budget.
			400	+	o.mu.Lock()
			401	+	for n := range anns {
			402	+	delete(o.pendingAnns, n)
			403	+	}
			404	+	o.mu.Unlock()
			405	+	o.releaseAnnotations(annotationsBytes(anns))
			406	+	return
			407	+	}
			408	+	if ctx.Err() == nil && classify(err) == kindPermanent {
260		o.log.Error().Err(err).Int32("step", s.Number).Msg("UpdateJob refused")	409		o.log.Error().Err(err).Int32("step", s.Number).Msg("UpdateJob refused")
			410	+	if len(anns) > 0 {
			411	+	// The annotations may be what the server refused: the step update
			412	+	// alone must not be lost with them.
			413	+	o.mu.Lock()
			414	+	for n := range anns {
			415	+	delete(o.pendingAnns, n)
			416	+	}
			417	+	o.mu.Unlock()
			418	+	o.releaseAnnotations(annotationsBytes(anns))
			419	+	if err := o.retry(ctx, "UpdateJob", func(c context.Context) error {
			420	+	_, err := o.client.UpdateJob(c, connect.NewRequest(&ermite.UpdateJobRequest{JobId: o.jobID, Steps: []*ermite.StepUpdate{s}}))
			421	+	return err
			422	+	}); err != nil && ctx.Err() == nil && classify(err) == kindPermanent {
			423	+	o.log.Error().Err(err).Int32("step", s.Number).Msg("UpdateJob refused without annotations")
			424	+	}
			425	+	}
			426	+	}
			427	+	}
			428	+
			429	+	func (o outbox) sendSummary(ctx context.Context, s summary) {
			430	+	err := o.retry(ctx, "UploadSummary", func(c context.Context) error {
			431	+	_, err := o.client.UploadSummary(c, connect.NewRequest(&ermite.UploadSummaryRequest{JobId: o.jobID, StepNumber: s.step, Markdown: s.markdown}))
			432	+	return err
			433	+	})
			434	+	if err != nil && ctx.Err() == nil && classify(err) == kindPermanent {
			435	+	o.log.Error().Err(err).Int32("step", s.step).Msg("UploadSummary refused, the summary is dropped")
261		}	436		}
262		}	437		}
263			438

A internal/host/results.go +290 -0

@@ -0,0 +1,290 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import (
	6	+	"context"
	7	+	"fmt"
	8	+	"strings"
	9	+	"time"
	10	+	"unicode/utf8"
	11	+
	12	+	"connectrpc.com/connect"
	13	+
	14	+	ermite "bnema.dev/ermite-api/gen/ermite"
	15	+
	16	+	"bnema.dev/ermite-runner/internal/execstream/execpb"
	17	+	)
	18	+
	19	+	// Features of the server that the host uses (GetVersionResponse.features).
	20	+	const (
	21	+	FeatureAnnotations = "ci.annotations"
	22	+	FeatureSummaries = "ci.summaries"
	23	+	)
	24	+
	25	+	// Limits of Annotation and UploadSummaryRequest (runner.proto). The executor
	26	+	// keeps within them; the guest is untrusted code, so the host enforces them
	27	+	// again, by dropping or cutting what is over rather than failing the job: the
	28	+	// server rejects a whole call that breaks one.
	29	+	const (
	30	+	maxAnnotationsPerLevel = 10
	31	+	maxAnnotationMessage = 4096
	32	+	maxAnnotationTitle = 255
	33	+	maxAnnotationFile = 1024
	34	+	maxSummaryBytes = 1 << 20
	35	+	)
	36	+
	37	+	// ServerFeatures asks the server for its features. It returns nil when it
	38	+	// cannot be reached: the optional results are then not sent.
	39	+	type ServerFeatures func(ctx context.Context) ([]string, error)
	40	+
	41	+	// jobFeatures is what the server accepts for this job.
	42	+	type jobFeatures struct{ annotations, summaries bool }
	43	+
	44	+	func featuresOf(list []string) jobFeatures {
	45	+	var f jobFeatures
	46	+	for _, x := range list {
	47	+	switch x {
	48	+	case FeatureAnnotations:
	49	+	f.annotations = true
	50	+	case FeatureSummaries:
	51	+	f.summaries = true
	52	+	}
	53	+	}
	54	+	return f
	55	+	}
	56	+
	57	+	// loadFeatures reads the features of the server for this job (GetVersion).
	58	+	func (j jobRun) loadFeatures(ctx context.Context, rt Runner) jobFeatures {
	59	+	if rt.Features == nil {
	60	+	return jobFeatures{}
	61	+	}
	62	+	cctx, cancel := context.WithTimeout(ctx, j.t.CallTimeout)
	63	+	defer cancel()
	64	+	list, err := rt.Features(cctx)
	65	+	if err != nil {
	66	+	j.log.Warn().Err(err).Msg("GetVersion failed: annotations and summaries are not sent for this job")
	67	+	return jobFeatures{}
	68	+	}
	69	+	return featuresOf(list)
	70	+	}
	71	+
	72	+	func levelOf(l execpb.AnnotationLevel) ermite.AnnotationLevel {
	73	+	switch l {
	74	+	case execpb.AnnotationLevel_ANNOTATION_LEVEL_NOTICE:
	75	+	return ermite.AnnotationLevel_ANNOTATION_LEVEL_NOTICE
	76	+	case execpb.AnnotationLevel_ANNOTATION_LEVEL_WARNING:
	77	+	return ermite.AnnotationLevel_ANNOTATION_LEVEL_WARNING
	78	+	case execpb.AnnotationLevel_ANNOTATION_LEVEL_FAILURE:
	79	+	return ermite.AnnotationLevel_ANNOTATION_LEVEL_FAILURE
	80	+	}
	81	+	return ermite.AnnotationLevel_ANNOTATION_LEVEL_UNSPECIFIED
	82	+	}
	83	+
	84	+	// cutRunes bounds s to n characters (code points), after making it valid UTF-8.
	85	+	// A string that is cut is copied: a substring would keep the whole allocation
	86	+	// of what the guest sent (up to a frame of 2 MiB) alive for as long as the
	87	+	// short string is, and a guest can open 1,000 steps.
	88	+	func cutRunes(s string, n int) string {
	89	+	s = strings.ToValidUTF8(s, "\ufffd")
	90	+	if utf8.RuneCountInString(s) <= n {
	91	+	return s
	92	+	}
	93	+	i := 0
	94	+	for k := range s {
	95	+	if i == n {
	96	+	return strings.Clone(s[:k])
	97	+	}
	98	+	i++
	99	+	}
	100	+	return s
	101	+	}
	102	+
	103	+	// annotationsFrom turns the annotations of a step into the ones of the
	104	+	// contract: the ones that break a rule of the contract are dropped (no level,
	105	+	// no message, a message over 4096 characters, more than ten of a level), the
	106	+	// numbers are made consistent (negative values and an end before the start
	107	+	// become "not given").
	108	+	func annotationsFrom(step int32, in []execpb.Annotation) []ermite.Annotation {
	109	+	var out []*ermite.Annotation
	110	+	count := map[ermite.AnnotationLevel]int{}
	111	+	for _, a := range in {
	112	+	lvl := levelOf(a.GetLevel())
	113	+	msg := strings.ToValidUTF8(a.GetMessage(), "\ufffd")
	114	+	if lvl == ermite.AnnotationLevel_ANNOTATION_LEVEL_UNSPECIFIED \|\| msg == "" \|\| utf8.RuneCountInString(msg) > maxAnnotationMessage {
	115	+	continue
	116	+	}
	117	+	if count[lvl] >= maxAnnotationsPerLevel {
	118	+	continue
	119	+	}
	120	+	count[lvl]++
	121	+	n := func(v int32) int32 { return max(v, 0) }
	122	+	o := &ermite.Annotation{
	123	+	Level: lvl, Title: cutRunes(a.GetTitle(), maxAnnotationTitle), Message: msg, StepNumber: step,
	124	+	StartLine: n(a.GetStartLine()), EndLine: n(a.GetEndLine()), StartColumn: n(a.GetStartColumn()), EndColumn: n(a.GetEndColumn()),
	125	+	}
	126	+	if f := strings.ToValidUTF8(a.GetFile(), "\ufffd"); utf8.RuneCountInString(f) <= maxAnnotationFile {
	127	+	o.File = f
	128	+	}
	129	+	if o.EndLine != 0 && o.EndLine < o.StartLine {
	130	+	o.EndLine = 0
	131	+	}
	132	+	out = append(out, o)
	133	+	}
	134	+	return out
	135	+	}
	136	+
	137	+	// stepAnnotations records the annotations of a step; they are sent with its
	138	+	// completion (UpdateJob replaces the annotations of the step by this list).
	139	+	func (j jobRun) stepAnnotations(a execpb.StepAnnotations) {
	140	+	j.mu.Lock()
	141	+	defer j.mu.Unlock()
	142	+	if j.violation != "" \|\| !j.features.annotations {
	143	+	return
	144	+	}
	145	+	if why := j.resultFrameProblemLocked("annotations", a.Step, j.annSeen); why != "" {
	146	+	j.mu.Unlock()
	147	+	j.violate("%s", why)
	148	+	j.mu.Lock()
	149	+	return
	150	+	}
	151	+	if j.annLists == nil {
	152	+	j.annLists = map[int32][]*ermite.Annotation{}
	153	+	}
	154	+	j.annSeen[a.Step] = true
	155	+	list := annotationsFrom(a.Step, a.Annotations)
	156	+	// The list stays in memory until the call that carries it is answered,
	157	+	// first here while its step runs, then in the outbox: all of it counts in
	158	+	// the one budget of the outbox, from now (ReserveAnnotations) to the answer
	159	+	// (sendStep). When there is no room (the server has been failing for long)
	160	+	// the list is dropped, and the log says so.
	161	+	n := annotationBytes(list)
	162	+	if !j.outbox.ReserveAnnotations(n) {
	163	+	j.log.Warn().Int32("step", a.Step).Int("bytes", n).Msg("too much is waiting to be sent to the server: the annotations of this step are dropped")
	164	+	// Only a count is kept (j.mu is held): the final report tells the user.
	165	+	j.annDropped += len(list)
	166	+	return
	167	+	}
	168	+	j.annLists[a.Step] = list
	169	+	}
	170	+
	171	+	// annotationsBytes is the size of the lists of a call.
	172	+	func annotationsBytes(m map[int32][]*ermite.Annotation) int {
	173	+	n := 0
	174	+	for _, l := range m {
	175	+	n += annotationBytes(l)
	176	+	}
	177	+	return n
	178	+	}
	179	+
	180	+	func annotationBytes(l []*ermite.Annotation) int {
	181	+	n := 0
	182	+	for _, a := range l {
	183	+	n += len(a.Title) + len(a.Message) + len(a.File) + 64
	184	+	}
	185	+	return n
	186	+	}
	187	+
	188	+	// resultFrameProblemLocked checks a frame that carries a result of a step
	189	+	// (annotations, summary). The executor sends each at most once per step, while
	190	+	// the step runs, just before it completes (the runner reads GITHUB_STEP_SUMMARY
	191	+	// once, after the step, and keeps the issues of a step in one list): anything
	192	+	// else is the guest misbehaving, and would let it queue unbounded data.
	193	+	func (j *jobRun) resultFrameProblemLocked(what string, step int32, seen map[int32]bool) string {
	194	+	u, ok := j.steps[step]
	195	+	switch {
	196	+	case !ok:
	197	+	return fmt.Sprintf("%s for step %d, which has not started", what, step)
	198	+	case u.State == ermite.StepState_STEP_STATE_COMPLETED:
	199	+	return fmt.Sprintf("%s for step %d, which is completed", what, step)
	200	+	case seen[step]:
	201	+	return fmt.Sprintf("%s for step %d, which already sent them", what, step)
	202	+	}
	203	+	return ""
	204	+	}
	205	+
	206	+	// takeAnnotations returns the list recorded for step n, once.
	207	+	func (j jobRun) takeAnnotations(n int32) map[int32][]ermite.Annotation {
	208	+	l, ok := j.annLists[n]
	209	+	if !ok {
	210	+	return nil
	211	+	}
	212	+	delete(j.annLists, n)
	213	+	return map[int32][]*ermite.Annotation{n: l}
	214	+	}
	215	+
	216	+	// stepSummary queues UploadSummary for a step that wrote GITHUB_STEP_SUMMARY.
	217	+	// The bytes count in the bounded memory of the outbox, like log lines: the call
	218	+	// blocks while too much is queued.
	219	+	func (j jobRun) stepSummary(s execpb.StepSummary) {
	220	+	j.mu.Lock()
	221	+	if j.violation != "" \|\| !j.features.summaries {
	222	+	j.mu.Unlock()
	223	+	return
	224	+	}
	225	+	if why := j.resultFrameProblemLocked("a summary", s.Step, j.sumSeen); why != "" {
	226	+	j.mu.Unlock()
	227	+	j.violate("%s", why)
	228	+	return
	229	+	}
	230	+	j.sumSeen[s.Step] = true
	231	+	j.mu.Unlock()
	232	+	md := strings.ToValidUTF8(s.Markdown, "\ufffd")
	233	+	if len(md) > maxSummaryBytes {
	234	+	j.log.Warn().Int32("step", s.Step).Int("bytes", len(md)).Msg("a step summary over 1 MiB is dropped")
	235	+	return
	236	+	}
	237	+	j.outbox.Summary(s.Step, md)
	238	+	}
	239	+
	240	+	// uploadSummaryClient is what the outbox needs for summaries.
	241	+	var _ interface {
	242	+	UploadSummary(context.Context, connect.Request[ermite.UploadSummaryRequest]) (connect.Response[ermite.UploadSummaryResponse], error)
	243	+	} = jobClient(nil)
	244	+
	245	+	// allPendingAnnotations are the annotations for CompleteJob: the lists no
	246	+	// UpdateJob has carried, and those of steps that never completed (the
	247	+	// executor was stopped), in step order.
	248	+	func (j jobRun) allPendingAnnotations() []ermite.Annotation {
	249	+	m := map[int32][]*ermite.Annotation{}
	250	+	for _, a := range j.outbox.PendingAnnotations() {
	251	+	m[a.StepNumber] = append(m[a.StepNumber], a)
	252	+	}
	253	+	j.mu.Lock()
	254	+	for n, l := range j.annLists {
	255	+	m[n] = l
	256	+	}
	257	+	j.mu.Unlock()
	258	+	return flattenAnnotations(m)
	259	+	}
	260	+
	261	+	// droppedAnnotationsLine is the warning the user gets when annotations were
	262	+	// dropped because the backlog of reports to the server was full. The text is
	263	+	// ermite's own (the official runner has no such backlog); it carries no
	264	+	// annotation content, only the count, which the host coalesces over the whole
	265	+	// job. Empty when nothing was dropped.
	266	+	func droppedAnnotationsLine(n int) string {
	267	+	switch {
	268	+	case n <= 0:
	269	+	return ""
	270	+	case n == 1:
	271	+	return "##[warning]1 annotation was not reported because the reporting backlog was full."
	272	+	}
	273	+	return fmt.Sprintf("##[warning]%d annotations were not reported because the reporting backlog was full.", n)
	274	+	}
	275	+
	276	+	// reportDroppedAnnotations appends the one warning line to the job log, after
	277	+	// the outbox is closed (the queue is full, or gone: it is not used) and before
	278	+	// CompleteJob, with a slice of the report budget of its own so that a server
	279	+	// that keeps failing cannot take the time CompleteJob needs.
	280	+	func (j *jobRun) reportDroppedAnnotations(ctx context.Context, budget time.Duration) {
	281	+	j.mu.Lock()
	282	+	line := droppedAnnotationsLine(j.annDropped)
	283	+	j.mu.Unlock()
	284	+	if line == "" {
	285	+	return
	286	+	}
	287	+	actx, cancel := context.WithTimeout(ctx, budget)
	288	+	defer cancel()
	289	+	j.appendLogLine(actx, line)
	290	+	}

A internal/host/results_test.go +636 -0

@@ -0,0 +1,636 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import (
	6	+	"context"
	7	+	"errors"
	8	+	"fmt"
	9	+	"io"
	10	+	"strings"
	11	+	"sync/atomic"
	12	+	"testing"
	13	+	"time"
	14	+	"unsafe"
	15	+
	16	+	"connectrpc.com/connect"
	17	+	"github.com/bnema/zerowrap"
	18	+
	19	+	ermite "bnema.dev/ermite-api/gen/ermite"
	20	+
	21	+	"bnema.dev/ermite-runner/internal/execstream"
	22	+	"bnema.dev/ermite-runner/internal/execstream/execpb"
	23	+	)
	24	+
	25	+	func annFrame(c execstream.Conn, step int, as ...execpb.Annotation) {
	26	+	send(c, &execpb.Frame{Body: &execpb.Frame_StepAnnotations{StepAnnotations: &execpb.StepAnnotations{Step: int32(step), Annotations: as}}})
	27	+	}
	28	+
	29	+	func sumFrame(c *execstream.Conn, step int, md string) {
	30	+	send(c, &execpb.Frame{Body: &execpb.Frame_StepSummary{StepSummary: &execpb.StepSummary{Step: int32(step), Markdown: md}}})
	31	+	}
	32	+
	33	+	func stepDoneOutcome(c *execstream.Conn, n int, name string, concl, outcome execpb.StepConclusion) {
	34	+	send(c, &execpb.Frame{Body: &execpb.Frame_StepCompleted{StepCompleted: &execpb.StepCompleted{Number: int32(n), Name: name, Conclusion: concl, Outcome: outcome, UnixNano: time.Now().UnixNano()}}})
	35	+	}
	36	+
	37	+	const (
	38	+	lWarn = execpb.AnnotationLevel_ANNOTATION_LEVEL_WARNING
	39	+	lFail = execpb.AnnotationLevel_ANNOTATION_LEVEL_FAILURE
	40	+	)
	41	+
	42	+	// resultsScript runs a job whose step 2 has annotations, a summary and an
	43	+	// outcome that differs from its conclusion (continue-on-error).
	44	+	func resultsScript(extra func(c *execstream.Conn)) script {
	45	+	return func(_ testing.T, c execstream.Conn, run execpb.Run, _ <-chan execpb.Cancel) {
	46	+	seenRun.Store(run)
	47	+	stepStart(c, 1, "Set up job")
	48	+	stepDone(c, 1, "Set up job", cOK)
	49	+	stepStart(c, 2, "Run it")
	50	+	logLineFrame(c, 2, "hi", false)
	51	+	annFrame(c, 2,
	52	+	&execpb.Annotation{Level: lWarn, Title: "T", Message: "careful", File: "a.go", StartLine: 3, EndLine: 4},
	53	+	&execpb.Annotation{Level: lFail, Message: "broken"})
	54	+	sumFrame(c, 2, "# Summary\n")
	55	+	stepDoneOutcome(c, 2, "Run it", cOK, cFail)
	56	+	if extra != nil {
	57	+	extra(c)
	58	+	}
	59	+	stepStart(c, 3, "Complete job")
	60	+	stepDone(c, 3, "Complete job", cOK)
	61	+	jobDone(c, cOK, nil, false)
	62	+	}
	63	+	}
	64	+
	65	+	// seenRun is the last Run frame the scripted executor received.
	66	+	var seenRun atomic.Pointer[execpb.Run]
	67	+
	68	+	func runResultsJob(t testing.T, sc script, tweak func(harness)) *harness {
	69	+	t.Helper()
	70	+	h := newHarness(t, sc)
	71	+	if tweak != nil {
	72	+	tweak(h)
	73	+	}
	74	+	h.srv.jobs = []*ermite.Job{testJob("j1")}
	75	+	stop := h.run(t)
	76	+	eventually(t, "CompleteJob", func() bool { return h.srv.completeCount() == 1 })
	77	+	if err := stop(); err != nil {
	78	+	t.Fatal(err)
	79	+	}
	80	+	return h
	81	+	}
	82	+
	83	+	func TestAnnotationsSummariesAndOutcomeAreForwarded(t *testing.T) {
	84	+	h := runResultsJob(t, resultsScript(nil), nil)
	85	+	if r := seenRun.Load(); r == nil \|\| !r.Job.SendAnnotations \|\| !r.Job.SendSummaries {
	86	+	t.Errorf("the executor was not told to send: %+v", r)
	87	+	}
	88	+	s := h.srv
	89	+	s.mu.Lock()
	90	+	defer s.mu.Unlock()
	91	+	// the annotations travel with the UpdateJob that completes the step
	92	+	var withAnn *ermite.UpdateJobRequest
	93	+	for _, u := range s.updates {
	94	+	if len(u.Annotations) > 0 {
	95	+	withAnn = u
	96	+	}
	97	+	}
	98	+	if withAnn == nil \|\| len(withAnn.Steps) != 1 \|\| withAnn.Steps[0].Number != 2 \|\| withAnn.Steps[0].State != ermite.StepState_STEP_STATE_COMPLETED {
	99	+	t.Fatalf("annotations did not ride the completion of step 2: %+v", s.updates)
	100	+	}
	101	+	got := s.annots[2]
	102	+	if len(got) != 2 \|\| got[0].Level != ermite.AnnotationLevel_ANNOTATION_LEVEL_WARNING \|\| got[0].Title != "T" \|\| got[0].File != "a.go" \|\|
	103	+	got[0].StartLine != 3 \|\| got[0].EndLine != 4 \|\| got[0].StepNumber != 2 \|\| got[1].Level != ermite.AnnotationLevel_ANNOTATION_LEVEL_FAILURE {
	104	+	t.Errorf("annotations %+v", got)
	105	+	}
	106	+	if s.summaries[2] != "# Summary\n" {
	107	+	t.Errorf("summaries %v", s.summaries)
	108	+	}
	109	+	u := s.steps[2]
	110	+	if u.Conclusion != ermite.CiConclusion_CI_CONCLUSION_SUCCESS \|\| u.Outcome != ermite.CiConclusion_CI_CONCLUSION_FAILURE {
	111	+	t.Errorf("conclusion %v outcome %v", u.Conclusion, u.Outcome)
	112	+	}
	113	+	if o := s.steps[3].Outcome; o != ermite.CiConclusion_CI_CONCLUSION_UNSPECIFIED {
	114	+	t.Errorf("a step that sends no outcome carries none: %v", o)
	115	+	}
	116	+	// nothing is left for CompleteJob when the UpdateJob went through
	117	+	if n := len(s.completes[0].Annotations); n != 0 {
	118	+	t.Errorf("CompleteJob repeats %d annotations", n)
	119	+	}
	120	+	}
	121	+
	122	+	// Without the server features, nothing is sent.
	123	+	func TestResultsAreNotSentWithoutTheFeatures(t *testing.T) {
	124	+	h := runResultsJob(t, resultsScript(nil), func(h *harness) {
	125	+	h.runner.Features = func(context.Context) ([]string, error) { return []string{"ci.runners"}, nil }
	126	+	})
	127	+	if r := seenRun.Load(); r == nil \|\| r.Job.SendAnnotations \|\| r.Job.SendSummaries {
	128	+	t.Errorf("the executor was told to send: %+v", r)
	129	+	}
	130	+	s := h.srv
	131	+	s.mu.Lock()
	132	+	defer s.mu.Unlock()
	133	+	if len(s.annots) != 0 \|\| len(s.summaries) != 0 {
	134	+	t.Errorf("annotations %v summaries %v", s.annots, s.summaries)
	135	+	}
	136	+	if len(s.completes[0].Annotations) != 0 {
	137	+	t.Error("CompleteJob carries annotations")
	138	+	}
	139	+	// the outcome is part of the StepUpdate, not of a feature
	140	+	if s.steps[2].Outcome != ermite.CiConclusion_CI_CONCLUSION_FAILURE {
	141	+	t.Error("outcome")
	142	+	}
	143	+	}
	144	+
	145	+	func TestFeaturesUnreachableMeansNothingIsSent(t *testing.T) {
	146	+	h := runResultsJob(t, resultsScript(nil), func(h *harness) {
	147	+	h.runner.Features = func(context.Context) ([]string, error) { return nil, errors.New("down") }
	148	+	})
	149	+	h.srv.mu.Lock()
	150	+	defer h.srv.mu.Unlock()
	151	+	if len(h.srv.annots) != 0 \|\| len(h.srv.summaries) != 0 {
	152	+	t.Error("sent without knowing the features")
	153	+	}
	154	+	}
	155	+
	156	+	// The host enforces the limits of the contract on what the guest sends: ten
	157	+	// per level, 4096 characters, titles of 255, valid numbers.
	158	+	func TestGuestAnnotationsAreBoundedByTheHost(t *testing.T) {
	159	+	var many []*execpb.Annotation
	160	+	for range 12 {
	161	+	many = append(many, &execpb.Annotation{Level: lWarn, Message: "w"})
	162	+	}
	163	+	many = append(many,
	164	+	&execpb.Annotation{Level: lFail, Message: strings.Repeat("é", 4097)}, // too long: dropped
	165	+	&execpb.Annotation{Level: lFail, Message: strings.Repeat("é", 4096), Title: strings.Repeat("t", 300)}, // kept, title cut
	166	+	&execpb.Annotation{Level: lFail, Message: ""}, // empty: dropped
	167	+	&execpb.Annotation{Level: execpb.AnnotationLevel_ANNOTATION_LEVEL_UNSPECIFIED, Message: "no level"}, // dropped
	168	+	&execpb.Annotation{Level: lFail, Message: "bad numbers", StartLine: -4, EndLine: -1, StartColumn: 5}, // numbers made valid
	169	+	&execpb.Annotation{Level: lFail, Message: "end before", StartLine: 9, EndLine: 3},
	170	+	)
	171	+	sc := func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	172	+	stepStart(c, 1, "Set up job")
	173	+	annFrame(c, 1, many...)
	174	+	stepDone(c, 1, "Set up job", cOK)
	175	+	jobDone(c, cOK, nil, false)
	176	+	}
	177	+	h := runResultsJob(t, sc, nil)
	178	+	s := h.srv
	179	+	s.mu.Lock()
	180	+	defer s.mu.Unlock()
	181	+	count := map[ermite.AnnotationLevel]int{}
	182	+	for _, a := range s.annots[1] {
	183	+	count[a.Level]++
	184	+	}
	185	+	if count[ermite.AnnotationLevel_ANNOTATION_LEVEL_WARNING] != 10 \|\| count[ermite.AnnotationLevel_ANNOTATION_LEVEL_FAILURE] != 3 {
	186	+	t.Fatalf("counts %v", count)
	187	+	}
	188	+	var cut, neg, end *ermite.Annotation
	189	+	for _, a := range s.annots[1] {
	190	+	switch a.Message {
	191	+	case strings.Repeat("é", 4096):
	192	+	cut = a
	193	+	case "bad numbers":
	194	+	neg = a
	195	+	case "end before":
	196	+	end = a
	197	+	}
	198	+	}
	199	+	if cut == nil \|\| len([]rune(cut.Title)) != 255 {
	200	+	t.Errorf("title: %v", cut)
	201	+	}
	202	+	if neg == nil \|\| neg.StartLine != 0 \|\| neg.EndLine != 0 \|\| neg.StartColumn != 5 {
	203	+	t.Errorf("%+v", neg)
	204	+	}
	205	+	if end == nil \|\| end.StartLine != 9 \|\| end.EndLine != 0 {
	206	+	t.Errorf("%+v", end)
	207	+	}
	208	+	if v := s.violations; len(v) != 0 {
	209	+	t.Error(v)
	210	+	}
	211	+	}
	212	+
	213	+	func TestGuestResultsForAnUnstartedStepFailTheJob(t *testing.T) {
	214	+	h := hostile(t, "annotations for step 9, which has not started", func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	215	+	stepStart(c, 1, "Set up job")
	216	+	annFrame(c, 9, &execpb.Annotation{Level: lWarn, Message: "x"})
	217	+	time.Sleep(50 * time.Millisecond)
	218	+	})
	219	+	_ = h
	220	+	}
	221	+
	222	+	// The annotations of a step that never completes (the executor is stopped) are
	223	+	// sent with CompleteJob.
	224	+	func TestAnnotationsOfAnUnfinishedStepGoWithCompleteJob(t *testing.T) {
	225	+	sc := func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	226	+	stepStart(c, 1, "Set up job")
	227	+	stepDone(c, 1, "Set up job", cOK)
	228	+	stepStart(c, 2, "Run it")
	229	+	annFrame(c, 2, &execpb.Annotation{Level: lWarn, Message: "last words"})
	230	+	// the executor dies here, without completing step 2 or the job
	231	+	}
	232	+	h := runResultsJob(t, sc, nil)
	233	+	h.srv.mu.Lock()
	234	+	defer h.srv.mu.Unlock()
	235	+	if len(h.srv.completes[0].Annotations) != 1 \|\| h.srv.completes[0].Annotations[0].Message != "last words" {
	236	+	t.Errorf("%+v", h.srv.completes[0].Annotations)
	237	+	}
	238	+	}
	239	+
	240	+	// UpdateJob that fails and is retried: the annotations are not duplicated,
	241	+	// since the list replaces the stored one.
	242	+	func TestAnnotationsSurviveARetriedUpdateJob(t *testing.T) {
	243	+	var fails atomic.Int32
	244	+	h := runResultsJob(t, resultsScript(nil), func(h *harness) {
	245	+	h.srv.updateHook = func(_ int, r *ermite.UpdateJobRequest) error {
	246	+	if len(r.Annotations) > 0 && fails.Add(1) <= 2 {
	247	+	return connect.NewError(connect.CodeUnavailable, nil)
	248	+	}
	249	+	return nil
	250	+	}
	251	+	})
	252	+	h.srv.mu.Lock()
	253	+	defer h.srv.mu.Unlock()
	254	+	if len(h.srv.annots[2]) != 2 {
	255	+	t.Errorf("%d annotations after retries", len(h.srv.annots[2]))
	256	+	}
	257	+	}
	258	+
	259	+	// A refused UpdateJob (invalid_argument) does not lose the step update: the
	260	+	// step is resent without its annotations.
	261	+	func TestRefusedAnnotationsDoNotLoseTheStep(t *testing.T) {
	262	+	h := runResultsJob(t, resultsScript(nil), func(h *harness) {
	263	+	h.srv.updateHook = func(_ int, r *ermite.UpdateJobRequest) error {
	264	+	if len(r.Annotations) > 0 {
	265	+	return connect.NewError(connect.CodeInvalidArgument, nil)
	266	+	}
	267	+	return nil
	268	+	}
	269	+	})
	270	+	h.srv.mu.Lock()
	271	+	defer h.srv.mu.Unlock()
	272	+	if u := h.srv.steps[2]; u == nil \|\| u.State != ermite.StepState_STEP_STATE_COMPLETED {
	273	+	t.Errorf("step 2: %v", u)
	274	+	}
	275	+	if len(h.srv.annots[2]) != 0 {
	276	+	t.Error("refused annotations stored")
	277	+	}
	278	+	if len(h.srv.completes[0].Annotations) != 0 {
	279	+	t.Error("a refused list is sent again with CompleteJob")
	280	+	}
	281	+	}
	282	+
	283	+	func TestSummaryOverOneMiBIsDropped(t *testing.T) {
	284	+	sc := func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	285	+	stepStart(c, 1, "Set up job")
	286	+	sumFrame(c, 1, strings.Repeat("x", 1<<20+1))
	287	+	stepDone(c, 1, "Set up job", cOK)
	288	+	stepStart(c, 2, "Run it")
	289	+	sumFrame(c, 2, strings.Repeat("y", 1<<20))
	290	+	stepDone(c, 2, "Run it", cOK)
	291	+	jobDone(c, cOK, nil, false)
	292	+	}
	293	+	h := runResultsJob(t, sc, nil)
	294	+	h.srv.mu.Lock()
	295	+	defer h.srv.mu.Unlock()
	296	+	if _, has := h.srv.summaries[1]; has {
	297	+	t.Error("a summary over 1 MiB was sent")
	298	+	}
	299	+	if len(h.srv.summaries[2]) != 1<<20 \|\| h.srv.summaries[2][0] != 'y' {
	300	+	t.Errorf("summary of %d bytes", len(h.srv.summaries[2]))
	301	+	}
	302	+	}
	303	+
	304	+	// One summary and one list of annotations per step, sent while the step runs
	305	+	// (GO-002): a second one, or one for a completed step, is the guest
	306	+	// misbehaving, and it would let it queue unbounded data.
	307	+	func TestGuestSecondSummaryFailsTheJob(t *testing.T) {
	308	+	hostile(t, "a summary for step 1, which already sent them", func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	309	+	stepStart(c, 1, "Set up job")
	310	+	sumFrame(c, 1, "one")
	311	+	sumFrame(c, 1, "two")
	312	+	time.Sleep(50 * time.Millisecond)
	313	+	})
	314	+	}
	315	+
	316	+	func TestGuestSummaryForACompletedStepFailsTheJob(t *testing.T) {
	317	+	hostile(t, "a summary for step 1, which is completed", func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	318	+	stepStart(c, 1, "Set up job")
	319	+	stepDone(c, 1, "Set up job", cOK)
	320	+	sumFrame(c, 1, "late")
	321	+	time.Sleep(50 * time.Millisecond)
	322	+	})
	323	+	}
	324	+
	325	+	func TestGuestSecondAnnotationListFailsTheJob(t *testing.T) {
	326	+	hostile(t, "annotations for step 1, which already sent them", func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	327	+	stepStart(c, 1, "Set up job")
	328	+	annFrame(c, 1, &execpb.Annotation{Level: lWarn, Message: "a"})
	329	+	annFrame(c, 1, &execpb.Annotation{Level: lWarn, Message: "b"})
	330	+	time.Sleep(50 * time.Millisecond)
	331	+	})
	332	+	}
	333	+
	334	+	func TestGuestAnnotationsForACompletedStepFailTheJob(t *testing.T) {
	335	+	hostile(t, "annotations for step 1, which is completed", func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	336	+	stepStart(c, 1, "Set up job")
	337	+	stepDone(c, 1, "Set up job", cOK)
	338	+	annFrame(c, 1, &execpb.Annotation{Level: lWarn, Message: "late"})
	339	+	time.Sleep(50 * time.Millisecond)
	340	+	})
	341	+	}
	342	+
	343	+	// The summaries count in the memory the outbox bounds, and backpressure holds
	344	+	// the producer while the server does not answer (GO-002).
	345	+	func TestSummaryBytesAreBoundedByTheOutbox(t *testing.T) {
	346	+	release := make(chan struct{})
	347	+	cl := &blockingSummaryClient{release: release}
	348	+	o := newOutbox(cl, "j1", fastTiming(), func(error) {}, zerowrapNop())
	349	+	ctx, cancel := context.WithCancel(context.Background())
	350	+	defer cancel()
	351	+	o.start(ctx)
	352	+	defer close(release)
	353	+	big := strings.Repeat("x", 1<<20)
	354	+	go func() {
	355	+	for i := 1; i <= 40; i++ { // 40 MiB offered, 16 MiB allowed in memory
	356	+	o.Summary(int32(i), big)
	357	+	}
	358	+	}()
	359	+	time.Sleep(500 * time.Millisecond)
	360	+	o.mu.Lock()
	361	+	queued := o.queued
	362	+	o.mu.Unlock()
	363	+	if queued > maxQueuedBytes+len(big)+64 {
	364	+	t.Errorf("%d bytes queued, the bound is %d", queued, maxQueuedBytes)
	365	+	}
	366	+	if queued < maxQueuedBytes/2 {
	367	+	t.Errorf("only %d bytes queued: the summaries are not counted?", queued)
	368	+	}
	369	+	}
	370	+
	371	+	type blockingSummaryClient struct {
	372	+	stubClient
	373	+	release chan struct{}
	374	+	}
	375	+
	376	+	func (c blockingSummaryClient) UploadSummary(ctx context.Context, _ connect.Request[ermite.UploadSummaryRequest]) (*connect.Response[ermite.UploadSummaryResponse], error) {
	377	+	select {
	378	+	case <-c.release:
	379	+	case <-ctx.Done():
	380	+	return nil, ctx.Err()
	381	+	}
	382	+	return connect.NewResponse(&ermite.UploadSummaryResponse{}), nil
	383	+	}
	384	+
	385	+	// A string cut by the host must not keep the allocation of the frame the guest
	386	+	// sent it in (GO-003): the cut copy has its own memory.
	387	+	func TestCutStringsDoNotRetainTheGuestAllocation(t *testing.T) {
	388	+	big := strings.Repeat("a", 1<<20)
	389	+	t0 := cutRunes(big, 255)
	390	+	if len(t0) != 255 {
	391	+	t.Fatal(len(t0))
	392	+	}
	393	+	if unsafe.StringData(t0) == unsafe.StringData(big) {
	394	+	t.Error("cutRunes returns a substring of its argument")
	395	+	}
	396	+	name := cutName(big)
	397	+	if len(name) != maxNameLen \|\| unsafe.StringData(name) == unsafe.StringData(big) {
	398	+	t.Error("cutName returns a substring of its argument")
	399	+	}
	400	+	// an annotation that is kept whole (not cut) is not copied: its message is
	401	+	// within 4096 characters, a frame cannot make it retain more than that
	402	+	// through a substring because the host does not slice it.
	403	+	a := annotationsFrom(1, []*execpb.Annotation{{Level: lWarn, Message: "m", Title: big, File: strings.Repeat("f", 2000)}})
	404	+	if len(a) != 1 \|\| len(a[0].Title) != 255 \|\| unsafe.StringData(a[0].Title) == unsafe.StringData(big) {
	405	+	t.Errorf("title %d", len(a[0].Title))
	406	+	}
	407	+	if a[0].File != "" {
	408	+	t.Error("a file over 1,024 characters is dropped")
	409	+	}
	410	+	}
	411	+
	412	+	// A message of the frame is bounded by execstream.MaxFrame: a summary of 1 MiB
	413	+	// fits.
	414	+	func TestSummaryFitsAFrame(t *testing.T) {
	415	+	f := &execpb.Frame{Body: &execpb.Frame_StepSummary{StepSummary: &execpb.StepSummary{Step: 1, Markdown: strings.Repeat("x", 1<<20)}}}
	416	+	c := execstream.NewConn(&discard{})
	417	+	if err := c.Send(f); err != nil {
	418	+	t.Fatal(err)
	419	+	}
	420	+	}
	421	+
	422	+	type discard struct{}
	423	+
	424	+	func (discard) Write(p []byte) (int, error) { return len(p), nil }
	425	+	func (discard) Read([]byte) (int, error) { select {} }
	426	+
	427	+	func zerowrapNop() zerowrap.Logger {
	428	+	return zerowrap.New(zerowrap.Config{Level: "error", Format: "json", Output: io.Discard})
	429	+	}
	430	+
	431	+	// GO-006: the reader of the stream of the sandbox waits in the outbox for room
	432	+	// when the summaries fill the budget and the server keeps failing; the hard
	433	+	// stop of the job must wake it, or the job outlives its deadline and the
	434	+	// shutdown waits for ever. Heartbeats work, every upload fails transiently,
	435	+	// summaries of distinct steps fill the queue, the runner is stopped.
	436	+	func TestHardStopReleasesAProducerWaitingForRoom(t *testing.T) {
	437	+	sc := func(_ testing.T, c execstream.Conn, _ execpb.Run, cancels <-chan execpb.Cancel) {
	438	+	big := strings.Repeat("s", 1<<20)
	439	+	for i := 1; i <= 30; i++ { // 30 MiB of summaries, 16 MiB of room
	440	+	stepStart(c, i, "step")
	441	+	sumFrame(c, i, big)
	442	+	}
	443	+	// the executor ignores the cancellation, as a stuck one would
	444	+	<-cancels
	445	+	time.Sleep(time.Hour)
	446	+	}
	447	+	h := newHarness(t, sc)
	448	+	h.runner.Timing.ShutdownGrace = 500 * time.Millisecond
	449	+	h.runner.Timing.ShutdownReport = time.Second
	450	+	h.runner.Timing.StopDeadline = 5 * time.Second
	451	+	h.srv.summaryHook = func(*ermite.UploadSummaryRequest) error { return connect.NewError(connect.CodeUnavailable, nil) }
	452	+	h.srv.jobs = []*ermite.Job{testJob("j1")}
	453	+	stop := h.run(t)
	454	+	eventually(t, "the queue to fill", func() bool {
	455	+	h.srv.mu.Lock()
	456	+	defer h.srv.mu.Unlock()
	457	+	return len(h.srv.beats) > 2
	458	+	})
	459	+	time.Sleep(300 * time.Millisecond) // the reader is stuck in Summary by now
	460	+	start := time.Now()
	461	+	done := make(chan error, 1)
	462	+	go func() { done <- stop() }()
	463	+	select {
	464	+	case <-done:
	465	+	case <-time.After(15 * time.Second):
	466	+	t.Fatal("the job did not end after the hard stop: the stream reader is stuck waiting for room")
	467	+	}
	468	+	if took := time.Since(start); took > 10*time.Second {
	469	+	t.Errorf("shutdown took %v", took)
	470	+	}
	471	+	if h.srv.completeCount() != 1 {
	472	+	t.Errorf("the job was not reported: %d CompleteJob", h.srv.completeCount())
	473	+	}
	474	+	}
	475	+
	476	+	// GO-007: annotations count in the budget of the outbox from the moment the
	477	+	// host holds them until the call that carries them is answered. With the
	478	+	// server not answering and 400 steps that each ended with the largest list the
	479	+	// contract allows, the memory held stays within the budget and the lists over
	480	+	// it are dropped, with a log line.
	481	+	func TestAnnotationsWaitingForTheServerAreBounded(t *testing.T) {
	482	+	cl := &blockingUpdateClient{release: make(chan struct{})}
	483	+	defer close(cl.release)
	484	+	logs := &logBuf{}
	485	+	tm := fastTiming()
	486	+	ctx, cancel := context.WithCancel(context.Background())
	487	+	defer cancel()
	488	+	j := &jobRun{client: cl, t: tm, ctx: ctx, job: &ermite.Job{JobId: "j1"}, steps: map[int32]*ermite.StepUpdate{},
	489	+	annSeen: map[int32]bool{}, sumSeen: map[int32]bool{}, features: jobFeatures{annotations: true},
	490	+	cancelCh: make(chan *execpb.Cancel, 1), log: zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: logs})}
	491	+	j.outbox = newOutbox(cl, "j1", tm, func(error) {}, j.log)
	492	+	j.outbox.start(ctx)
	493	+	var list []*execpb.Annotation
	494	+	for _, l := range []execpb.AnnotationLevel{lWarn, lFail, execpb.AnnotationLevel_ANNOTATION_LEVEL_NOTICE} {
	495	+	for range 10 {
	496	+	list = append(list, &execpb.Annotation{Level: l, Message: strings.Repeat("m", 4096), Title: strings.Repeat("t", 255)})
	497	+	}
	498	+	}
	499	+	for n := int32(1); n <= 400; n++ { // 400 x about 135 KiB offered, 16 MiB of room
	500	+	j.stepStarted(&execpb.StepStarted{Number: n, Name: "s"})
	501	+	j.stepAnnotations(&execpb.StepAnnotations{Step: n, Annotations: list})
	502	+	j.stepCompleted(&execpb.StepCompleted{Number: n, Name: "s", Conclusion: cOK})
	503	+	}
	504	+	j.outbox.mu.Lock()
	505	+	held := annotationsBytes(j.outbox.pendingAnns)
	506	+	queued := j.outbox.queued
	507	+	j.outbox.mu.Unlock()
	508	+	if held > maxQueuedBytes {
	509	+	t.Errorf("%d bytes of annotations wait for the server, the budget is %d", held, maxQueuedBytes)
	510	+	}
	511	+	if queued > maxQueuedBytes {
	512	+	t.Errorf("%d bytes counted in the outbox, the budget is %d", queued, maxQueuedBytes)
	513	+	}
	514	+	if held < maxQueuedBytes/2 {
	515	+	t.Errorf("only %d bytes held: the annotations are dropped too early", held)
	516	+	}
	517	+	if !strings.Contains(logs.String(), "the annotations of this step are dropped") {
	518	+	t.Error("dropping annotations is not logged")
	519	+	}
	520	+	}
	521	+
	522	+	type blockingUpdateClient struct {
	523	+	stubClient
	524	+	release chan struct{}
	525	+	}
	526	+
	527	+	func (c blockingUpdateClient) UpdateJob(ctx context.Context, _ connect.Request[ermite.UpdateJobRequest]) (*connect.Response[ermite.UpdateJobResponse], error) {
	528	+	select {
	529	+	case <-c.release:
	530	+	return connect.NewResponse(&ermite.UpdateJobResponse{}), nil
	531	+	case <-ctx.Done():
	532	+	return nil, ctx.Err()
	533	+	}
	534	+	}
	535	+
	536	+	// Once the call that carried a list is answered, its bytes leave the budget.
	537	+	func TestAnnotationBudgetIsGivenBack(t *testing.T) {
	538	+	var ob *outbox
	539	+	h := runResultsJob(t, resultsScript(nil), nil)
	540	+	_ = ob
	541	+	if got := h.srv.annots[2]; len(got) != 2 {
	542	+	t.Fatalf("annotations %v", got)
	543	+	}
	544	+	cl := &stubClient{}
	545	+	o := newOutbox(cl, "j1", fastTiming(), func(error) {}, zerowrapNop())
	546	+	ctx, cancel := context.WithCancel(context.Background())
	547	+	defer cancel()
	548	+	o.start(ctx)
	549	+	list := []*ermite.Annotation{{Level: ermite.AnnotationLevel_ANNOTATION_LEVEL_WARNING, Message: "m", StepNumber: 2}}
	550	+	n := annotationBytes(list)
	551	+	if !o.ReserveAnnotations(n) {
	552	+	t.Fatal("no room")
	553	+	}
	554	+	o.Step(&ermite.StepUpdate{Number: 2}, map[int32][]*ermite.Annotation{2: list})
	555	+	eventually(t, "the call to be answered", func() bool {
	556	+	o.mu.Lock()
	557	+	defer o.mu.Unlock()
	558	+	return o.queued == 0
	559	+	})
	560	+	}
	561	+
	562	+	// GO-009: annotations dropped for lack of room are told to the user with one
	563	+	// warning line in the job log, appended after the outbox is closed, without
	564	+	// annotation content.
	565	+	func TestDroppedAnnotationsAreReportedInTheLog(t *testing.T) {
	566	+	var list []*execpb.Annotation
	567	+	for _, l := range []execpb.AnnotationLevel{lWarn, lFail, execpb.AnnotationLevel_ANNOTATION_LEVEL_NOTICE} {
	568	+	for range 10 {
	569	+	list = append(list, &execpb.Annotation{Level: l, Message: "SECRET-CONTENT" + strings.Repeat("m", 4080), Title: strings.Repeat("t", 255)})
	570	+	}
	571	+	}
	572	+	const steps = 200 // about 135 KiB each: 27 MB offered, 16 MiB of room
	573	+	sc := func(_ testing.T, c execstream.Conn, _ execpb.Run, _ <-chan execpb.Cancel) {
	574	+	for n := 1; n <= steps; n++ {
	575	+	stepStart(c, n, "step")
	576	+	annFrame(c, n, list...)
	577	+	stepDone(c, n, "step", cOK)
	578	+	}
	579	+	jobDone(c, cOK, nil, false)
	580	+	}
	581	+	h := newHarness(t, sc)
	582	+	h.runner.Timing.CompleteDeadline = 3 * time.Second
	583	+	// the server is blocked: every UpdateJob fails transiently, for ever
	584	+	h.srv.updateHook = func(int, *ermite.UpdateJobRequest) error { return connect.NewError(connect.CodeUnavailable, nil) }
	585	+	h.srv.jobs = []*ermite.Job{testJob("j1")}
	586	+	stop := h.run(t)
	587	+	eventually(t, "CompleteJob", func() bool { return h.srv.completeCount() == 1 })
	588	+	if err := stop(); err != nil {
	589	+	t.Fatal(err)
	590	+	}
	591	+	h.srv.mu.Lock()
	592	+	defer h.srv.mu.Unlock()
	593	+	var found []string
	594	+	for _, l := range h.srv.lines {
	595	+	if strings.Contains(l, "were not reported because the reporting backlog was full.") {
	596	+	found = append(found, l)
	597	+	}
	598	+	if strings.Contains(l, "SECRET-CONTENT") {
	599	+	t.Error("annotation content reached the job log")
	600	+	}
	601	+	}
	602	+	if len(found) != 1 {
	603	+	t.Fatalf("%d lines about dropped annotations: %q", len(found), found)
	604	+	}
	605	+	var n int
	606	+	if _, err := fmt.Sscanf(found[0], "##[warning]%d annotations were not reported because the reporting backlog was full.", &n); err != nil \|\| n < 30 \|\| n > steps*30 \|\| n%30 != 0 {
	607	+	t.Errorf("%q (n=%d, %v)", found[0], n, err)
	608	+	}
	609	+	if h.srv.lines[len(h.srv.lines)-1] != found[0] {
	610	+	t.Error("the line is not the last of the log")
	611	+	}
	612	+	}
	613	+
	614	+	func TestDroppedAnnotationsLine(t *testing.T) {
	615	+	for n, want := range map[int]string{
	616	+	0: "", -1: "",
	617	+	1: "##[warning]1 annotation was not reported because the reporting backlog was full.",
	618	+	30: "##[warning]30 annotations were not reported because the reporting backlog was full.",
	619	+	} {
	620	+	if got := droppedAnnotationsLine(n); got != want {
	621	+	t.Errorf("%d: %q", n, got)
	622	+	}
	623	+	}
	624	+	}
	625	+
	626	+	// A job that drops nothing writes no such line.
	627	+	func TestNoDroppedAnnotationsNoLine(t *testing.T) {
	628	+	h := runResultsJob(t, resultsScript(nil), nil)
	629	+	h.srv.mu.Lock()
	630	+	defer h.srv.mu.Unlock()
	631	+	for _, l := range h.srv.lines {
	632	+	if strings.Contains(l, "reporting backlog") {
	633	+	t.Errorf("%q", l)
	634	+	}
	635	+	}
	636	+	}

M internal/host/rpc.go +18 -0


@@ -106,6 +106,24 @@ func newClient(baseURL, token string, base http.RoundTripper, insecure bool) erm
106	return ermiteconnect.NewRunnerServiceClient(hc, strings.TrimRight(baseURL, "/")+APIPath)	106		return ermiteconnect.NewRunnerServiceClient(hc, strings.TrimRight(baseURL, "/")+APIPath)
107	}	107		}
108		108
		109	+	// ServerFeaturesFunc returns the function that reads the features of the
		110	+	// server with GetVersion, which needs no authentication. It is called once
		111	+	// per job.
		112	+	func (c Config) ServerFeaturesFunc(url string) ServerFeatures {
		113	+	hc := &http.Client{
		114	+	Transport: bearer{base: http.DefaultTransport, allowInsecure: c.InsecureHTTP},
		115	+	CheckRedirect: func(http.Request, []http.Request) error { return http.ErrUseLastResponse },
		116	+	}
		117	+	client := ermiteconnect.NewServerServiceClient(hc, strings.TrimRight(url, "/")+APIPath)
		118	+	return func(ctx context.Context) ([]string, error) {
		119	+	resp, err := client.GetVersion(ctx, connect.NewRequest(&ermite.GetVersionRequest{}))
		120	+	if err != nil {
		121	+	return nil, err
		122	+	}
		123	+	return resp.Msg.GetFeatures(), nil
		124	+	}
		125	+	}
		126	+
109	// APIPath is where ermite serves its API under the base URL, as in ermite's own	127		// APIPath is where ermite serves its API under the base URL, as in ermite's own
110	// client (internal/adapters/client.APIPath there).	128		// client (internal/adapters/client.APIPath there).
111	const APIPath = "/-/api"	129		const APIPath = "/-/api"

M internal/host/runner.go +5 -0


@@ -32,6 +32,10 @@ type Runner struct {
32	// Job builds the client of a job from its job token.	32		// Job builds the client of a job from its job token.
33	Job func(jobToken string) ermiteconnect.RunnerServiceClient	33		Job func(jobToken string) ermiteconnect.RunnerServiceClient
34	Timing Timing	34		Timing Timing
		35	+	// Features lists the features of the server (GetVersion). Annotations and
		36	+	// step summaries are sent only when it says "ci.annotations" and
		37	+	// "ci.summaries". Nil means neither is sent.
		38	+	Features ServerFeatures
35		39
36	// now returns the current time; tests replace it.	40		// now returns the current time; tests replace it.
37	now func() time.Time	41		now func() time.Time

@@ -182,6 +186,7 @@ func (r Runner) startJob(ctx context.Context, log zerowrap.Logger, job ermite.
182	r: r, job: job, client: r.Job(job.JobToken), t: t, ctx: jctx, cancel: cancel,	186		r: r, job: job, client: r.Job(job.JobToken), t: t, ctx: jctx, cancel: cancel,
183	log: zerowrap.Logger{Logger: log.With().Str("job_id", job.JobId).Int64("run_id", job.RunId).Int32("attempt", job.Attempt).Logger()},	187		log: zerowrap.Logger{Logger: log.With().Str("job_id", job.JobId).Int64("run_id", job.RunId).Int32("attempt", job.Attempt).Logger()},
184	receivedAt: r.clock(), cancelCh: make(chan execpb.Cancel, 1), steps: map[int32]ermite.StepUpdate{},	188		receivedAt: r.clock(), cancelCh: make(chan execpb.Cancel, 1), steps: map[int32]ermite.StepUpdate{},
		189	+	annSeen: map[int32]bool{}, sumSeen: map[int32]bool{},
185	}	190		}
186	jr.log.Info().Str("job_key", job.JobKey).Msg("job assigned")	191		jr.log.Info().Str("job_key", job.JobKey).Msg("job assigned")
187	r.active.Add(1)	192		r.active.Add(1)

M internal/host/shutdown_test.go +4 -0


@@ -27,6 +27,10 @@ func (c stubClient) UpdateJob(context.Context, connect.Request[ermite.UpdateJo
27	return connect.NewResponse(&ermite.UpdateJobResponse{}), nil	27		return connect.NewResponse(&ermite.UpdateJobResponse{}), nil
28	}	28		}
29		29
		30	+	func (c stubClient) UploadSummary(context.Context, connect.Request[ermite.UploadSummaryRequest]) (*connect.Response[ermite.UploadSummaryResponse], error) {
		31	+	return connect.NewResponse(&ermite.UploadSummaryResponse{}), nil
		32	+	}
		33	+
30	func (c stubClient) AppendLog(ctx context.Context, r connect.Request[ermite.AppendLogRequest]) (*connect.Response[ermite.AppendLogResponse], error) {	34		func (c stubClient) AppendLog(ctx context.Context, r connect.Request[ermite.AppendLogRequest]) (*connect.Response[ermite.AppendLogResponse], error) {
31	c.mu.Lock()	35		c.mu.Lock()
32	hang := c.hang	36		hang := c.hang