Skip to content

Commit

Runner: step summaries, graceful cancel, debug logging

Each step's $GITHUB_STEP_SUMMARY is sent to g1t (masked, up to 1 MiB) instead of echoed into the log. A report's answer can say the run was cancelled: the running step's process group gets SIGINT, SIGTERM after 7.5 s and is killed 2.5 s later, then only if: always() and cancelled() steps and post steps run, and the job ends cancelled. A quiet step pings every 10 s so a cancellation reaches it. RUNNER_DEBUG=1 or ACTIONS_STEP_DEBUG among the job's variables turns on step debug logging, which also explains how each step's if: read.

syntaqxcommitted Parent111c3baBrowse files
4 files+316−240/4 viewed
+1−0
628628 self.log.line("##[error]The step ran past its time limit and was stopped.");
629629 false
630630 }
631+ Ok(Ended::Cancelled) => false,
631632 Err(error) => {
632633 self.log.line(&format!("##[error]docker could not be started: {error}"));
633634 false
+106−21
130130 &self.path_prepend
131131 }
132132
133+ /// How the job is going, for `success()`, `failure()`, `cancelled()`
134+ /// and `always()`: once the run is cancelled, only steps that ask for
135+ /// `always()` or `cancelled()` run.
133136 fn status(&self) -> Status {
134− if self.failed { Status::Failure } else { Status::Success }
137+ if report::cancelled() {
138+ Status::Cancelled
139+ } else if self.failed {
140+ Status::Failure
141+ } else {
142+ Status::Success
143+ }
144+ }
145+
146+ /// `job.status`.
147+ fn status_word(&self) -> &'static str {
148+ if report::cancelled() {
149+ "cancelled"
150+ } else if self.failed {
151+ "failure"
152+ } else {
153+ "success"
154+ }
135155 }
136156
137157 /// The contexts an expression in a step can use.
139159 let mut contexts = self.contexts.clone();
140160 contexts.insert("env".into(), Value::Object(env.iter().map(|(k, v)| (k.clone(), Value::String(v.clone()))).collect()));
141161 contexts.insert("steps".into(), Value::Object(frame.steps.clone()));
142− contexts.insert("job".into(), containers::job_context(if self.failed { "failure" } else { "success" }, &self.job_context));
162+ contexts.insert("job".into(), containers::job_context(self.status_word(), &self.job_context));
143163 if let Some(inputs) = &frame.inputs {
144164 contexts.insert("inputs".into(), inputs.clone());
145165 }
214234 if let Ok(values) = files::key_values(&StepFiles::read(&files.state)) {
215235 state.extend(values);
216236 }
217− let summary = StepFiles::read(&files.summary);
218− if !summary.trim().is_empty() {
219− self.log.line("##[group]Step summary");
220− for line in summary.lines() {
221− self.log.line(line);
222− }
223− self.log.line("##[endgroup]");
224− }
237+ // The step's job summary, for the run's page (report.rs).
238+ self.log.summary(&StepFiles::read(&files.summary));
225239 (outputs, state)
226240 }
227241
329343 self.log.line("##[error]The step ran past its time limit and was stopped.");
330344 false
331345 }
346+ Ok(Ended::Cancelled) => false,
332347 Err(error) => {
333348 self.log.line(&format!("##[error]{program} could not be started: {error}"));
334349 false
341356 /// Runs one step of a frame. Returns whether it succeeded (its
342357 /// conclusion). `number` is the step the log belongs to.
343358 pub(crate) fn step(&mut self, frame: &mut Frame, step: &Map<String, Value>, number: u32, report: bool, defaults: &Map<String, Value>) -> bool {
359+ // A cancellation heard during an earlier step (which it stopped) or
360+ // since: from here on, only cleanup steps run, and none is stopped
361+ // for it again.
362+ if report::cancelled() {
363+ report::take_cancel();
364+ }
344365 let env_before = self.env_context(frame);
345366 let contexts = self.contexts_for(frame, &env_before);
346367 let title = match step.get("name").map(expr::to_text) {
348369 None => default_title(step),
349370 };
350371 let condition = step.get("if").map(expr::to_text).unwrap_or_default();
351− let run_it = match self.with_scope(&contexts, |scope| expr::condition(&condition, scope)) {
372+ let read = self.with_scope(&contexts, |scope| expr::condition(&condition, scope));
373+ // Debug logging: how the step's `if` read, as GitHub's runner says.
374+ if self.debug {
375+ let shown = if condition.trim().is_empty() { "success()" } else { condition.trim() };
376+ self.log.line(&format!("##[debug]Evaluating condition for step: '{title}'"));
377+ self.log.line(&format!("##[debug]Evaluating: {shown}"));
378+ match &read {
379+ Ok(result) => self.log.line(&format!("##[debug]Result: {result}")),
380+ Err(problem) => self.log.line(&format!("##[debug]Failed: {problem}")),
381+ }
382+ }
383+ let run_it = match read {
352384 Ok(run_it) => run_it,
353385 Err(problem) => {
354386 self.log.line(&format!("##[error]The step's `if` does not read: {problem}"));
441473 (false, BTreeMap::new())
442474 };
443475
444− let outcome = if ok { "success" } else { "failure" };
445− let conclusion = if ok || continue_on_error { "success" } else { "failure" };
446− if !ok && continue_on_error {
476+ // A step the cancellation stopped ends cancelled, not failed.
477+ let stopped = !ok && report::cancelled();
478+ let outcome = if ok {
479+ "success"
480+ } else if stopped {
481+ "cancelled"
482+ } else {
483+ "failure"
484+ };
485+ let conclusion = if ok || continue_on_error {
486+ "success"
487+ } else {
488+ outcome
489+ };
490+ if !ok && continue_on_error && !stopped {
447491 self.log.line("##[warning]The step failed, and `continue-on-error` lets the job go on.");
448492 }
449493 if let Some(id) = &id {
504548 out
505549 }
506550
551+/// Whether `::debug::` lines are shown and steps' conditions explained:
552+/// `ACTIONS_STEP_DEBUG` as a secret or a variable set to `true`, or a
553+/// re-run with debug logging, which sets it and `RUNNER_DEBUG=1` among the
554+/// job's variables.
555+fn step_debug(contexts: &Map<String, Value>, variables: &Value) -> bool {
556+ let named = |name: &str| {
557+ contexts
558+ .get("secrets")
559+ .and_then(|s| s.get(name))
560+ .or_else(|| contexts.get("vars").and_then(|v| v.get(name)))
561+ .or_else(|| variables.get(name))
562+ .is_some_and(|v| expr::to_text(v).eq_ignore_ascii_case("true"))
563+ };
564+ named("ACTIONS_STEP_DEBUG") || variables.get("RUNNER_DEBUG").is_some_and(|v| expr::to_text(v) == "1")
565+}
566+
507567 fn setup(mut spec: Value, api: Api) -> Result<Job> {
508568 let masks: Vec<String> = spec["masks"].as_array().map(|m| m.iter().filter_map(|v| v.as_str().map(str::to_owned)).collect()).unwrap_or_default();
509569 let log = Log::new(api, masks);
533593
534594 let mut contexts: Map<String, Value> = spec["contexts"].as_object().cloned().unwrap_or_default();
535595 contexts.insert("github".into(), spec["github"].clone());
536− let debug = contexts
537− .get("secrets")
538− .and_then(|s| s.get("ACTIONS_STEP_DEBUG"))
539− .or_else(|| contexts.get("vars").and_then(|v| v.get("ACTIONS_STEP_DEBUG")))
540− .is_some_and(|v| expr::to_text(v) == "true");
596+ let debug = step_debug(&contexts, &spec["variables"]);
541597
542598 // `timeoutMinutes` is how the API spelled it before its bodies were
543599 // `snake_case`.
710766 outputs.insert(name.clone(), Value::String(expr::to_text(&value)));
711767 }
712768 }
713− let conclusion = if job.failed { "failure" } else { "success" };
769+ // Cancelled, the job ends so however its cleanup went (and g1t holds
770+ // to that whatever it is told).
771+ let conclusion = if report::cancelled() {
772+ "cancelled"
773+ } else if job.failed {
774+ "failure"
775+ } else {
776+ "success"
777+ };
714778 job.log.done(conclusion, &outputs, None);
715779 }
716780
743807 }
744808 };
745809 run_job(&mut job);
746− if job.failed { 1 } else { 0 }
810+ if job.failed || report::cancelled() { 1 } else { 0 }
811+}
812+
813+#[cfg(test)]
814+mod tests {
815+ use serde_json::{Map, Value, json};
816+
817+ use super::step_debug;
818+
819+ #[test]
820+ fn debug_logging_comes_from_a_secret_a_variable_or_a_debug_rerun() {
821+ let contexts = |value: Value| -> Map<String, Value> { serde_json::from_value(value).unwrap() };
822+ let none = json!({});
823+ assert!(!step_debug(&contexts(json!({ "secrets": {}, "vars": {} })), &none));
824+ assert!(step_debug(&contexts(json!({ "secrets": { "ACTIONS_STEP_DEBUG": "true" } })), &none));
825+ assert!(step_debug(&contexts(json!({ "vars": { "ACTIONS_STEP_DEBUG": "TRUE" } })), &none));
826+ assert!(!step_debug(&contexts(json!({ "vars": { "ACTIONS_STEP_DEBUG": "false" } })), &none));
827+ // A re-run with debug logging sets these among the job's variables.
828+ assert!(step_debug(&contexts(json!({})), &json!({ "RUNNER_DEBUG": "1" })));
829+ assert!(step_debug(&contexts(json!({})), &json!({ "ACTIONS_STEP_DEBUG": "true" })));
830+ assert!(!step_debug(&contexts(json!({})), &json!({ "RUNNER_DEBUG": "0" })));
831+ }
747832 }
+86−1
119119 pub(crate) enum Ended {
120120 Exited(i32),
121121 TimedOut,
122+ /// The run was cancelled: it was interrupted, then stopped.
123+ Cancelled,
124+}
125+
126+/// After a cancellation, how long a step has after SIGINT before SIGTERM,
127+/// and after SIGTERM before it is killed, as GitHub's runner waits.
128+const INTERRUPT_GRACE: Duration = Duration::from_millis(7500);
129+const TERMINATE_GRACE: Duration = Duration::from_millis(2500);
130+
131+/// Sends `signal` to the process's group (it leads its own), so what the
132+/// step started hears it too. Windows has no signals: it is left to `kill`.
133+fn signal(child: &std::process::Child, signal: &str) {
134+ if cfg!(unix) {
135+ let _ = Command::new("kill")
136+ .args([format!("-{signal}"), "--".into(), format!("-{}", child.id())])
137+ .stdout(Stdio::null())
138+ .stderr(Stdio::null())
139+ .status();
140+ }
122141 }
123142
124143 /// Runs the command, sending its output (stdout and stderr together, a
125144 /// line at a time) through `commands` to the log, until it ends or
126145 /// `timeout` passes.
127−pub(crate) fn run(mut command: Command, timeout: Duration, log: &mut Log, commands: &mut Commands) -> std::io::Result<Ended> {
146+pub(crate) fn run(command: Command, timeout: Duration, log: &mut Log, commands: &mut Commands) -> std::io::Result<Ended> {
147+ run_until(command, timeout, log, commands, &super::report::interrupt)
148+}
149+
150+/// `run`, stopping the process gracefully once `interrupt` says so.
151+fn run_until(
152+ mut command: Command,
153+ timeout: Duration,
154+ log: &mut Log,
155+ commands: &mut Commands,
156+ interrupt: &dyn Fn() -> bool,
157+) -> std::io::Result<Ended> {
128158 command.stdin(Stdio::null()).stdout(Stdio::piped()).stderr(Stdio::piped());
159+ // A group of its own, so a cancellation reaches what the step started.
160+ #[cfg(unix)]
161+ std::os::unix::process::CommandExt::process_group(&mut command, 0);
129162 let mut child = command.spawn()?;
130163 let (sender, lines) = mpsc::channel::<String>();
131164 let mut readers = Vec::new();
158191 drop(sender);
159192 let deadline = Instant::now() + timeout;
160193 let mut timed_out = false;
194+ // When the cancellation reached it, and which signal it has had.
195+ let mut interrupted: Option<(Instant, u8)> = None;
161196 loop {
162197 match lines.recv_timeout(Duration::from_millis(250)) {
163198 Ok(line) => {
176211 }
177212 if Instant::now() >= deadline {
178213 timed_out = true;
214+ signal(&child, "KILL");
179215 let _ = child.kill();
180216 break;
181217 }
218+ // Cancelled: SIGINT, then SIGTERM, then killed, as on GitHub.
219+ match interrupted {
220+ None if interrupt() => {
221+ log.line("##[error]The operation was canceled.");
222+ signal(&child, "INT");
223+ interrupted = Some((Instant::now(), 1));
224+ }
225+ Some((at, 1)) if at.elapsed() >= INTERRUPT_GRACE => {
226+ signal(&child, "TERM");
227+ interrupted = Some((Instant::now(), 2));
228+ }
229+ Some((at, 2)) if at.elapsed() >= TERMINATE_GRACE => {
230+ signal(&child, "KILL");
231+ let _ = child.kill();
232+ break;
233+ }
234+ _ => {}
235+ }
236+ if interrupted.is_some() && matches!(child.try_wait(), Ok(Some(_))) {
237+ // The step is gone; what it started may still hold its output.
238+ signal(&child, "KILL");
239+ break;
240+ }
182241 }
183242 let status = child.wait()?;
184243 for reader in readers {
193252 if timed_out {
194253 return Ok(Ended::TimedOut);
195254 }
255+ if interrupted.is_some() {
256+ return Ok(Ended::Cancelled);
257+ }
196258 Ok(Ended::Exited(status.code().unwrap_or(1)))
197259 }
198260
200262 mod tests {
201263 use super::parse_command;
202264
265+ /// A cancelled step hears SIGINT, and its own trap runs.
266+ #[cfg(unix)]
267+ #[test]
268+ fn a_cancelled_step_is_interrupted_and_may_clean_up() {
269+ use super::{Commands, Ended, run_until};
270+ use crate::actions::report::{Api, Log};
271+ use std::process::Command;
272+ use std::time::{Duration, Instant};
273+
274+ let api = Api { base: "http://127.0.0.1:9".into(), job: "job_1".into(), token: "t".into() };
275+ let mut log = Log::new(api, Vec::new());
276+ let mut command = Command::new("sh");
277+ command.args(["-c", "trap 'echo cleaned up; exit 3' INT; echo started; while true; do sleep 0.1; done"]);
278+ let began = Instant::now();
279+ let ask = move || began.elapsed() >= Duration::from_millis(600);
280+ let ended = run_until(command, Duration::from_secs(60), &mut log, &mut Commands::default(), &ask).unwrap();
281+ assert!(matches!(ended, Ended::Cancelled));
282+ assert!(began.elapsed() < Duration::from_secs(8), "SIGINT ended it, not the kill after the grace period");
283+ let text = log.buffered();
284+ assert!(text.contains("The operation was canceled."), "{text}");
285+ assert!(text.contains("cleaned up"), "{text}");
286+ }
287+
203288 #[test]
204289 fn commands_are_read_with_their_properties() {
205290 let (name, properties, data) = parse_command("::error file=app.js,line=10,title=Bad%3A thing::Something%0Abroke").unwrap();
+123−2
11 //! Telling g1t how a job is going: its steps, its log in batches, its
22 //! annotations, and how it ended. Every report carries the job's token.
33
4+use std::sync::atomic::{AtomicBool, Ordering};
45 use std::time::{Duration, Instant};
56
67 use anyhow::Result;
1112 const FLUSH_EVERY: Duration = Duration::from_millis(1500);
1213 /// How much log is sent at once.
1314 const FLUSH_BYTES: usize = 64 * 1024;
15+/// The most one step may add to the job's summary, as on GitHub.
16+pub(crate) const MAX_SUMMARY_BYTES: usize = 1024 * 1024;
17+/// How long the runner goes without a report before it asks whether the
18+/// job was cancelled.
19+const PING_EVERY: Duration = Duration::from_secs(10);
20+
21+/// Whether the job was cancelled, as g1t's answers to its reports say.
22+struct Cancel {
23+ /// g1t said so.
24+ said: AtomicBool,
25+ /// The job has taken it in: the step it was on was stopped, and the
26+ /// cleanup steps that follow are not stopped for it again.
27+ taken: AtomicBool,
28+}
29+
30+impl Cancel {
31+ const fn new() -> Cancel {
32+ Cancel { said: AtomicBool::new(false), taken: AtomicBool::new(false) }
33+ }
34+
35+ /// Reads an answer to a report: `cancelled` when the run was cancelled.
36+ fn hear(&self, answer: &Value) {
37+ if answer["cancelled"].as_bool() == Some(true) {
38+ self.said.store(true, Ordering::Relaxed);
39+ }
40+ }
41+
42+ fn cancelled(&self) -> bool {
43+ self.said.load(Ordering::Relaxed)
44+ }
1445
46+ fn interrupt(&self) -> bool {
47+ self.cancelled() && !self.taken.load(Ordering::Relaxed)
48+ }
49+
50+ fn take(&self) {
51+ self.taken.store(true, Ordering::Relaxed);
52+ }
53+}
54+
55+/// This job's (one runs per process).
56+static CANCEL: Cancel = Cancel::new();
57+
58+/// Whether g1t said the job was cancelled.
59+pub(crate) fn cancelled() -> bool {
60+ CANCEL.cancelled()
61+}
62+
63+/// Whether a running step should be stopped: cancelled, and not yet taken in.
64+pub(crate) fn interrupt() -> bool {
65+ CANCEL.interrupt()
66+}
67+
68+/// The job has seen the cancellation: what runs from here is its cleanup.
69+pub(crate) fn take_cancel() {
70+ CANCEL.take();
71+}
72+
1573 pub(crate) struct Api {
1674 pub(crate) base: String,
1775 pub(crate) job: String,
3492 .timeout(Duration::from_secs(30))
3593 .send_json(json!({ "token": self.token, "report": report }));
3694 match sent {
37− Ok(_) => return,
95+ Ok(response) => {
96+ if let Ok(answer) = response.into_json::<Value>() {
97+ CANCEL.hear(&answer);
98+ }
99+ return;
100+ }
38101 // Refused: the job was cancelled or finished; nothing to retry.
39102 Err(ureq::Error::Status(code, _)) if (400..500).contains(&code) => return,
40103 Err(_) => std::thread::sleep(Duration::from_millis(500 * (attempt + 1))),
51114 step: u32,
52115 buffer: String,
53116 last: Instant,
117+ /// When anything was last sent, for the ping.
118+ sent: Instant,
54119 }
55120
56121 impl Log {
63128 step: 0,
64129 buffer: String::new(),
65130 last: Instant::now(),
131+ sent: Instant::now(),
66132 }
67133 }
68134
135+ /// What waits to be sent.
136+ #[cfg(all(test, unix))]
137+ pub(crate) fn buffered(&self) -> String {
138+ self.buffer.clone()
139+ }
140+
69141 /// Starts writing to step `number` (0 for the job's setup).
70142 pub(crate) fn step(&mut self, number: u32) {
71143 self.flush();
100172 }
101173 }
102174
103− /// Sends what is waiting if it has waited long enough.
175+ /// Sends what is waiting if it has waited long enough, and asks after
176+ /// the job when nothing has been sent for a while, so a cancellation
177+ /// reaches a step that prints nothing.
104178 pub(crate) fn tick(&mut self) {
105179 if !self.buffer.is_empty() && self.last.elapsed() >= FLUSH_EVERY {
106180 self.flush();
181+ } else if self.sent.elapsed() >= PING_EVERY {
182+ self.sent = Instant::now();
183+ self.api.report(json!({ "kind": "ping" }));
107184 }
108185 }
109186
112189 if self.buffer.is_empty() {
113190 return;
114191 }
192+ self.sent = Instant::now();
115193 let text = std::mem::take(&mut self.buffer);
116194 self.api.report(json!({ "kind": "log", "step": self.step, "text": text }));
117195 }
126204 self.api.report(json!({ "kind": "step", "number": number, "name": name, "status": status, "conclusion": conclusion }));
127205 }
128206
207+ /// What a step wrote to `$GITHUB_STEP_SUMMARY`, masked, for the run's
208+ /// page. More than 1 MiB is refused, as on GitHub, with an error in the
209+ /// log.
210+ pub(crate) fn summary(&mut self, markdown: &str) {
211+ if markdown.trim().is_empty() {
212+ return;
213+ }
214+ if markdown.len() > MAX_SUMMARY_BYTES {
215+ self.line(&format!(
216+ "##[error]$GITHUB_STEP_SUMMARY upload aborted: a step's summary may be up to 1024k, and this one is {}k.",
217+ markdown.len().div_ceil(1024)
218+ ));
219+ return;
220+ }
221+ let markdown = self.mask(markdown);
222+ self.flush();
223+ self.api.report(json!({ "kind": "summary", "step": self.step, "markdown": markdown }));
224+ }
225+
129226 pub(crate) fn annotation(&mut self, level: &str, message: &str, properties: &serde_json::Map<String, Value>) {
130227 let message = self.mask(message);
131228 let title = properties.get("title").and_then(Value::as_str).map(|title| self.mask(title));
188285 }
189286
190287 #[test]
288+ fn a_cancelled_answer_is_heard_once_and_taken_in() {
289+ let cancel = Cancel::new();
290+ cancel.hear(&json!({ "ok": true }));
291+ assert!(!cancel.cancelled());
292+ cancel.hear(&json!({ "ok": true, "cancelled": true }));
293+ assert!(cancel.cancelled() && cancel.interrupt());
294+ cancel.take();
295+ assert!(cancel.cancelled() && !cancel.interrupt(), "cleanup steps are not stopped again");
296+ cancel.hear(&json!({ "ok": true, "cancelled": false }));
297+ assert!(cancel.cancelled(), "a cancelled job stays cancelled");
298+ }
299+
300+ #[test]
301+ fn a_summary_past_its_limit_is_refused_in_the_log() {
302+ let mut log = log(&[]);
303+ log.summary("
304+");
305+ assert!(log.buffer.is_empty(), "an empty summary is not sent");
306+ log.summary(&"x".repeat(MAX_SUMMARY_BYTES + 1));
307+ assert!(log.buffer.contains("$GITHUB_STEP_SUMMARY upload aborted"));
308+ assert!(log.buffer.contains("1025k"));
309+ }
310+
311+ #[test]
191312 fn added_masks_cover_every_form() {
192313 let mut log = log(&[]);
193314 log.add_mask("line one\nline two");