| 1 | //! Telling g1t how a job is going: its steps, its log in batches, its |
| 2 | //! annotations, and how it ended. Every report carries the job's token. |
| 3 | |
| 4 | use std::sync::atomic::{AtomicBool, Ordering}; |
| 5 | use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; |
| 6 | |
| 7 | use anyhow::Result; |
| 8 | use g1t_actions::mask; |
| 9 | use serde_json::{Value, json}; |
| 10 | |
| 11 | /// How long log lines wait before they are sent: about a second, so a |
| 12 | /// running step's page follows it closely, at one write to g1t a second. |
| 13 | const FLUSH_EVERY: Duration = Duration::from_millis(1000); |
| 14 | /// How much log is sent at once. |
| 15 | const FLUSH_BYTES: usize = 64 * 1024; |
| 16 | /// The most one step may add to the job's summary, as on GitHub. |
| 17 | pub(crate) const MAX_SUMMARY_BYTES: usize = 1024 * 1024; |
| 18 | /// How long the runner goes without a report before it asks whether the |
| 19 | /// job was cancelled. |
| 20 | const PING_EVERY: Duration = Duration::from_secs(10); |
| 21 | |
| 22 | /// Whether the job was cancelled, as g1t's answers to its reports say. |
| 23 | struct Cancel { |
| 24 | /// g1t said so. |
| 25 | said: AtomicBool, |
| 26 | /// The job has taken it in: the step it was on was stopped, and the |
| 27 | /// cleanup steps that follow are not stopped for it again. |
| 28 | taken: AtomicBool, |
| 29 | } |
| 30 | |
| 31 | impl Cancel { |
| 32 | const fn new() -> Cancel { |
| 33 | Cancel { said: AtomicBool::new(false), taken: AtomicBool::new(false) } |
| 34 | } |
| 35 | |
| 36 | /// Reads an answer to a report: `cancelled` when the run was cancelled. |
| 37 | fn hear(&self, answer: &Value) { |
| 38 | if answer["cancelled"].as_bool() == Some(true) { |
| 39 | self.said.store(true, Ordering::Relaxed); |
| 40 | } |
| 41 | } |
| 42 | |
| 43 | fn cancelled(&self) -> bool { |
| 44 | self.said.load(Ordering::Relaxed) |
| 45 | } |
| 46 | |
| 47 | fn interrupt(&self) -> bool { |
| 48 | self.cancelled() && !self.taken.load(Ordering::Relaxed) |
| 49 | } |
| 50 | |
| 51 | fn take(&self) { |
| 52 | self.taken.store(true, Ordering::Relaxed); |
| 53 | } |
| 54 | } |
| 55 | |
| 56 | /// This job's (one runs per process). |
| 57 | static CANCEL: Cancel = Cancel::new(); |
| 58 | |
| 59 | /// Whether g1t said the job was cancelled. |
| 60 | pub(crate) fn cancelled() -> bool { |
| 61 | CANCEL.cancelled() |
| 62 | } |
| 63 | |
| 64 | /// Whether a running step should be stopped: cancelled, and not yet taken in. |
| 65 | pub(crate) fn interrupt() -> bool { |
| 66 | CANCEL.interrupt() |
| 67 | } |
| 68 | |
| 69 | /// The job has seen the cancellation: what runs from here is its cleanup. |
| 70 | pub(crate) fn take_cancel() { |
| 71 | CANCEL.take(); |
| 72 | } |
| 73 | |
| 74 | #[derive(Clone)] |
| 75 | pub(crate) struct Api { |
| 76 | pub(crate) base: String, |
| 77 | pub(crate) job: String, |
| 78 | pub(crate) token: String, |
| 79 | } |
| 80 | |
| 81 | impl Api { |
| 82 | /// The job's spec. With `rotate`, g1t spends the token it was asked |
| 83 | /// with and sends a new one beside the spec, which this takes for |
| 84 | /// everything after (`next_token`): a copy of the first left on the |
| 85 | /// runner's computer cannot fetch the job, its secrets or a G1T_TOKEN |
| 86 | /// again. A g1t that predates it sends none, and the token stays. |
| 87 | pub(crate) fn spec(&mut self, rotate: bool) -> Result<Value> { |
| 88 | let mut body = json!({ "token": self.token }); |
| 89 | if rotate { |
| 90 | body["rotate"] = json!(true); |
| 91 | } |
| 92 | let response = ureq::post(&format!("{}/actions/jobs/{}/spec", self.base, self.job)).timeout(Duration::from_secs(60)).send_json(body)?; |
| 93 | let mut spec: Value = response.into_json()?; |
| 94 | self.take_next_token(&mut spec); |
| 95 | Ok(spec) |
| 96 | } |
| 97 | |
| 98 | /// Takes the token a spec carries in place of the one it was fetched |
| 99 | /// with, and masks it in the log. |
| 100 | fn take_next_token(&mut self, spec: &mut Value) { |
| 101 | let next = spec.as_object_mut().and_then(|s| s.remove("next_token").or_else(|| s.remove("nextToken"))); |
| 102 | if let Some(next) = next.as_ref().and_then(Value::as_str).filter(|t| !t.is_empty()) { |
| 103 | self.token = next.to_owned(); |
| 104 | if let Some(masks) = spec.get_mut("masks").and_then(Value::as_array_mut) { |
| 105 | masks.push(json!(next)); |
| 106 | } |
| 107 | } |
| 108 | } |
| 109 | |
| 110 | /// Where to fetch another repository's action from: `{"source": "g1t", |
| 111 | /// "url", "ref", "token"}`, or `{"source": "github", "sha", "archive", |
| 112 | /// "note"}`: the commit GitHub's ref names, and whether g1t keeps its |
| 113 | /// archive (`action_archive`). Err holds why g1t |
| 114 | /// refused (`true`: the repository is private and may not be used |
| 115 | /// here), or that it could not be asked (`false`). |
| 116 | pub(crate) fn action(&self, repository: &str, git_ref: &str) -> std::result::Result<Value, (bool, String)> { |
| 117 | // The first job to use an action at a commit waits while g1t |
| 118 | // fetches and keeps its archive. |
| 119 | let sent = ureq::post(&format!("{}/actions/jobs/{}/action", self.base, self.job)) |
| 120 | .timeout(Duration::from_secs(120)) |
| 121 | .send_json(json!({ "token": self.token, "report": { "repository": repository, "ref": git_ref } })); |
| 122 | match sent { |
| 123 | Ok(response) => response.into_json().map_err(|error| (false, error.to_string())), |
| 124 | Err(ureq::Error::Status(code, response)) => { |
| 125 | let body: Value = response.into_json().unwrap_or(Value::Null); |
| 126 | let message = body["error"]["message"].as_str().unwrap_or("g1t did not answer.").to_owned(); |
| 127 | Err((code == 403, message)) |
| 128 | } |
| 129 | Err(error) => Err((false, error.to_string())), |
| 130 | } |
| 131 | } |
| 132 | |
| 133 | /// Downloads the archive g1t keeps of `repository` at `sha` to `to`. |
| 134 | pub(crate) fn action_archive(&self, repository: &str, sha: &str, to: &std::path::Path) -> std::result::Result<u64, String> { |
| 135 | let response = ureq::post(&format!("{}/actions/jobs/{}/archive", self.base, self.job)) |
| 136 | .timeout(Duration::from_secs(300)) |
| 137 | .send_json(json!({ "token": self.token, "report": { "repository": repository, "sha": sha } })) |
| 138 | .map_err(|error| match error { |
| 139 | ureq::Error::Status(code, response) => { |
| 140 | let body: Value = response.into_json().unwrap_or(Value::Null); |
| 141 | body["error"]["message"].as_str().map_or_else(|| format!("g1t answered {code}"), str::to_owned) |
| 142 | } |
| 143 | other => other.to_string(), |
| 144 | })?; |
| 145 | let mut file = std::fs::File::create(to).map_err(|error| error.to_string())?; |
| 146 | std::io::copy(&mut response.into_reader(), &mut file).map_err(|error| error.to_string()) |
| 147 | } |
| 148 | |
| 149 | /// An API with no address, which sends nothing: what the tests use, so |
| 150 | /// a step's run is not held up by reports that go nowhere (each one |
| 151 | /// tried three times, with waits between, over a second and a half). |
| 152 | #[cfg(test)] |
| 153 | pub(crate) fn offline() -> Api { |
| 154 | Api { base: String::new(), job: "job_1".into(), token: "t".into() } |
| 155 | } |
| 156 | |
| 157 | pub(crate) fn report(&self, report: Value) { |
| 158 | // No address: nowhere to send it (Api::offline). |
| 159 | if self.base.is_empty() { |
| 160 | return; |
| 161 | } |
| 162 | // A report that cannot be sent is tried a few times, then dropped: |
| 163 | // the job goes on, and g1t notices a silent job by itself. |
| 164 | for attempt in 0..3 { |
| 165 | let sent = ureq::post(&format!("{}/actions/jobs/{}", self.base, self.job)) |
| 166 | .timeout(Duration::from_secs(30)) |
| 167 | .send_json(json!({ "token": self.token, "report": report })); |
| 168 | match sent { |
| 169 | Ok(response) => { |
| 170 | if let Ok(answer) = response.into_json::<Value>() { |
| 171 | CANCEL.hear(&answer); |
| 172 | } |
| 173 | return; |
| 174 | } |
| 175 | // Refused: the job was cancelled or finished; nothing to retry. |
| 176 | Err(ureq::Error::Status(code, _)) if (400..500).contains(&code) => return, |
| 177 | Err(_) => std::thread::sleep(Duration::from_millis(500 * (attempt + 1))), |
| 178 | } |
| 179 | } |
| 180 | } |
| 181 | } |
| 182 | |
| 183 | /// The job's log, masked, sent in batches. `masks` holds every form of |
| 184 | /// every secret (`g1t_actions::mask`), longest first. |
| 185 | pub(crate) struct Log { |
| 186 | pub(crate) api: Api, |
| 187 | pub(crate) masks: Vec<String>, |
| 188 | step: u32, |
| 189 | buffer: String, |
| 190 | last: Instant, |
| 191 | /// When anything was last sent, for the ping. |
| 192 | sent: Instant, |
| 193 | /// The problem matchers steps added, which last the whole job. |
| 194 | pub(crate) matchers: super::matchers::Matchers, |
| 195 | /// The number of the last batch sent, 1 for the job's first: each |
| 196 | /// batch carries its own, and keeps it when it is sent again, so g1t |
| 197 | /// keeps a batch it already has once. |
| 198 | chunk: u64, |
| 199 | /// Everything sent so far, so a test reads the whole log however its |
| 200 | /// batches fell (`buffered`). |
| 201 | #[cfg(test)] |
| 202 | flushed: String, |
| 203 | } |
| 204 | |
| 205 | impl Log { |
| 206 | pub(crate) fn new(api: Api, mut masks: Vec<String>) -> Log { |
| 207 | masks.retain(|mask| !mask.is_empty()); |
| 208 | masks.sort_by_key(|mask| std::cmp::Reverse(mask.len())); |
| 209 | Log { |
| 210 | api, |
| 211 | masks, |
| 212 | step: 0, |
| 213 | buffer: String::new(), |
| 214 | last: Instant::now(), |
| 215 | sent: Instant::now(), |
| 216 | matchers: super::matchers::Matchers::default(), |
| 217 | chunk: 0, |
| 218 | #[cfg(test)] |
| 219 | flushed: String::new(), |
| 220 | } |
| 221 | } |
| 222 | |
| 223 | /// The log so far, what was sent and what waits to be, without the |
| 224 | /// time each line is stamped with. |
| 225 | #[cfg(test)] |
| 226 | pub(crate) fn buffered(&self) -> String { |
| 227 | unstamped(&format!("{}{}", self.flushed, self.buffer)) |
| 228 | } |
| 229 | |
| 230 | /// Starts writing to step `number` (0 for the job's setup). |
| 231 | pub(crate) fn step(&mut self, number: u32) { |
| 232 | self.flush(); |
| 233 | self.step = number; |
| 234 | } |
| 235 | |
| 236 | pub(crate) fn mask(&self, text: &str) -> String { |
| 237 | mask::apply(text, &self.masks) |
| 238 | } |
| 239 | |
| 240 | /// `::add-mask::`: masks `value` from here on, in every form it can |
| 241 | /// take (each line, base64, JSON-escaped), as a secret is. |
| 242 | pub(crate) fn add_mask(&mut self, value: &str) { |
| 243 | let mut added = false; |
| 244 | for variant in mask::variants(value) { |
| 245 | if !self.masks.contains(&variant) { |
| 246 | self.masks.push(variant); |
| 247 | added = true; |
| 248 | } |
| 249 | } |
| 250 | if added { |
| 251 | self.masks.sort_by_key(|mask| std::cmp::Reverse(mask.len())); |
| 252 | } |
| 253 | } |
| 254 | |
| 255 | /// Adds a line to the log, masked, each of its lines stamped with the |
| 256 | /// time, as GitHub's runner writes its logs |
| 257 | /// (`2026-10-12T09:41:07.1234567Z text`). |
| 258 | pub(crate) fn line(&mut self, text: &str) { |
| 259 | let masked = self.mask(text); |
| 260 | let at = stamp(SystemTime::now()); |
| 261 | for line in masked.split('\n') { |
| 262 | self.buffer.push_str(&at); |
| 263 | self.buffer.push(' '); |
| 264 | self.buffer.push_str(line); |
| 265 | self.buffer.push('\n'); |
| 266 | } |
| 267 | if self.buffer.len() >= FLUSH_BYTES || self.last.elapsed() >= FLUSH_EVERY { |
| 268 | self.flush(); |
| 269 | } |
| 270 | } |
| 271 | |
| 272 | /// Sends what is waiting if it has waited long enough, and asks after |
| 273 | /// the job when nothing has been sent for a while, so a cancellation |
| 274 | /// reaches a step that prints nothing. |
| 275 | pub(crate) fn tick(&mut self) { |
| 276 | if !self.buffer.is_empty() && self.last.elapsed() >= FLUSH_EVERY { |
| 277 | self.flush(); |
| 278 | } else if self.sent.elapsed() >= PING_EVERY { |
| 279 | self.sent = Instant::now(); |
| 280 | self.api.report(json!({ "kind": "ping" })); |
| 281 | } |
| 282 | } |
| 283 | |
| 284 | pub(crate) fn flush(&mut self) { |
| 285 | self.last = Instant::now(); |
| 286 | if self.buffer.is_empty() { |
| 287 | return; |
| 288 | } |
| 289 | self.sent = Instant::now(); |
| 290 | let text = std::mem::take(&mut self.buffer); |
| 291 | #[cfg(test)] |
| 292 | self.flushed.push_str(&text); |
| 293 | let report = self.log_report(text); |
| 294 | self.api.report(report); |
| 295 | } |
| 296 | |
| 297 | /// The next batch of the log, numbered. |
| 298 | fn log_report(&mut self, text: String) -> Value { |
| 299 | self.chunk += 1; |
| 300 | json!({ "kind": "log", "step": self.step, "chunk": self.chunk, "text": text }) |
| 301 | } |
| 302 | |
| 303 | /// Does `work` with the job's API on a thread of its own, writing |
| 304 | /// `waiting(seconds)` to the log, and sending it, every `every` it is |
| 305 | /// still going: a wait the job's page would otherwise show as a silent |
| 306 | /// log, such as g1t fetching an action's archive from GitHub. |
| 307 | pub(crate) fn waiting<T: Send + 'static>( |
| 308 | &mut self, |
| 309 | every: Duration, |
| 310 | work: impl FnOnce(Api) -> T + Send + 'static, |
| 311 | waiting: impl Fn(u64) -> String, |
| 312 | ) -> T { |
| 313 | self.flush(); |
| 314 | let api = self.api.clone(); |
| 315 | let (done, answer) = std::sync::mpsc::channel(); |
| 316 | let worker = std::thread::spawn(move || { |
| 317 | let _ = done.send(work(api)); |
| 318 | }); |
| 319 | let started = Instant::now(); |
| 320 | let result = loop { |
| 321 | match answer.recv_timeout(every) { |
| 322 | Ok(result) => break result, |
| 323 | Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { |
| 324 | self.line(&waiting(started.elapsed().as_secs())); |
| 325 | self.flush(); |
| 326 | } |
| 327 | // The work panicked: so does the job, as it would have. |
| 328 | Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => match worker.join() { |
| 329 | Err(panic) => std::panic::resume_unwind(panic), |
| 330 | Ok(()) => unreachable!("the work sends its result before it ends"), |
| 331 | }, |
| 332 | } |
| 333 | }; |
| 334 | let _ = worker.join(); |
| 335 | result |
| 336 | } |
| 337 | |
| 338 | pub(crate) fn steps(&self, names: &[String]) { |
| 339 | self.api.report(json!({ "kind": "steps", "steps": names })); |
| 340 | } |
| 341 | |
| 342 | pub(crate) fn step_state(&mut self, number: u32, name: &str, status: &str, conclusion: Option<&str>) { |
| 343 | self.flush(); |
| 344 | let name = self.mask(name); |
| 345 | self.api.report(json!({ "kind": "step", "number": number, "name": name, "status": status, "conclusion": conclusion })); |
| 346 | } |
| 347 | |
| 348 | /// What a step wrote to `$GITHUB_STEP_SUMMARY`, masked, for the run's |
| 349 | /// page. More than 1 MiB is refused, as on GitHub, with an error in the |
| 350 | /// log. |
| 351 | pub(crate) fn summary(&mut self, markdown: &str) { |
| 352 | if markdown.trim().is_empty() { |
| 353 | return; |
| 354 | } |
| 355 | if markdown.len() > MAX_SUMMARY_BYTES { |
| 356 | self.line(&format!( |
| 357 | "##[error]$GITHUB_STEP_SUMMARY upload aborted: a step's summary may be up to 1024k, and this one is {}k.", |
| 358 | markdown.len().div_ceil(1024) |
| 359 | )); |
| 360 | return; |
| 361 | } |
| 362 | let markdown = self.mask(markdown); |
| 363 | self.flush(); |
| 364 | self.api.report(json!({ "kind": "summary", "step": self.step, "markdown": markdown })); |
| 365 | } |
| 366 | |
| 367 | /// An annotation, from `::error::` and its kin or a problem matcher: |
| 368 | /// its `file`, `line`, `col`, `endLine` and `endColumn` as GitHub's |
| 369 | /// commands spell them, sent as `file`, `line`, `column`, `end_line` |
| 370 | /// and `end_column`. |
| 371 | pub(crate) fn annotation(&mut self, level: &str, message: &str, properties: &serde_json::Map<String, Value>) { |
| 372 | let report = self.annotation_report(level, message, properties); |
| 373 | self.api.report(report); |
| 374 | } |
| 375 | |
| 376 | fn annotation_report(&self, level: &str, message: &str, properties: &serde_json::Map<String, Value>) -> Value { |
| 377 | let message = self.mask(message); |
| 378 | let title = properties.get("title").and_then(Value::as_str).map(|title| self.mask(title)); |
| 379 | let number = |keys: &[&str]| keys.iter().find_map(|key| properties.get(*key).and_then(Value::as_str)).and_then(|n| n.trim().parse::<u32>().ok()); |
| 380 | json!({ |
| 381 | "kind": "annotation", |
| 382 | "level": level, |
| 383 | "message": message, |
| 384 | "title": title, |
| 385 | "file": properties.get("file"), |
| 386 | "line": number(&["line"]), |
| 387 | "column": number(&["col"]), |
| 388 | "end_line": number(&["endLine"]), |
| 389 | "end_column": number(&["endColumn"]), |
| 390 | }) |
| 391 | } |
| 392 | |
| 393 | pub(crate) fn done(&mut self, conclusion: &str, outputs: &serde_json::Map<String, Value>, reason: Option<&str>) { |
| 394 | let outputs = self.withhold_secrets(outputs); |
| 395 | self.flush(); |
| 396 | self.api.report(json!({ "kind": "done", "conclusion": conclusion, "outputs": outputs, "reason": reason })); |
| 397 | } |
| 398 | |
| 399 | /// The job's outputs without any that hold a secret, as on GitHub: an |
| 400 | /// output goes to other jobs and to the run's page, where no mask |
| 401 | /// reaches. Each one left out is warned of in the log. |
| 402 | pub(crate) fn withhold_secrets(&mut self, outputs: &serde_json::Map<String, Value>) -> serde_json::Map<String, Value> { |
| 403 | let mut kept = serde_json::Map::new(); |
| 404 | for (name, value) in outputs { |
| 405 | let text = match value { |
| 406 | Value::String(text) => text.clone(), |
| 407 | other => other.to_string(), |
| 408 | }; |
| 409 | if mask::reveals(&text, &self.masks) { |
| 410 | self.line(&format!("##[warning]The output `{name}` was left out: it holds a secret.")); |
| 411 | continue; |
| 412 | } |
| 413 | kept.insert(name.clone(), value.clone()); |
| 414 | } |
| 415 | kept |
| 416 | } |
| 417 | } |
| 418 | |
| 419 | /// A time as GitHub's logs stamp each line: RFC 3339 in UTC, to a tenth |
| 420 | /// of a microsecond (`2026-10-12T09:41:07.1234567Z`). |
| 421 | pub(crate) fn stamp(at: SystemTime) -> String { |
| 422 | let since = at.duration_since(UNIX_EPOCH).unwrap_or_default(); |
| 423 | let seconds = since.as_secs(); |
| 424 | let (days, rest) = (seconds / 86_400, seconds % 86_400); |
| 425 | let (year, month, day) = civil(days as i64); |
| 426 | format!( |
| 427 | "{year:04}-{month:02}-{day:02}T{:02}:{:02}:{:02}.{:07}Z", |
| 428 | rest / 3600, |
| 429 | rest % 3600 / 60, |
| 430 | rest % 60, |
| 431 | since.subsec_nanos() / 100 |
| 432 | ) |
| 433 | } |
| 434 | |
| 435 | /// The calendar date `days` after 1970-01-01 (Howard Hinnant's |
| 436 | /// `civil_from_days`). |
| 437 | fn civil(days: i64) -> (i64, u32, u32) { |
| 438 | let z = days + 719_468; |
| 439 | let era = z.div_euclid(146_097); |
| 440 | let doe = z.rem_euclid(146_097); |
| 441 | let yoe = (doe - doe / 1460 + doe / 36_524 - doe / 146_096) / 365; |
| 442 | let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); |
| 443 | let mp = (5 * doy + 2) / 153; |
| 444 | let day = (doy - (153 * mp + 2) / 5 + 1) as u32; |
| 445 | let month = (if mp < 10 { mp + 3 } else { mp - 9 }) as u32; |
| 446 | let year = yoe + era * 400 + i64::from(month <= 2); |
| 447 | (year, month, day) |
| 448 | } |
| 449 | |
| 450 | /// A log without the time stamped at the start of each line. |
| 451 | #[cfg(test)] |
| 452 | pub(crate) fn unstamped(text: &str) -> String { |
| 453 | text.split_inclusive('\n') |
| 454 | .map(|line| match line.split_once(' ') { |
| 455 | Some((at, rest)) if at.len() == 28 && at.ends_with('Z') && at.as_bytes()[10] == b'T' => rest, |
| 456 | _ => line, |
| 457 | }) |
| 458 | .collect() |
| 459 | } |
| 460 | |
| 461 | #[cfg(test)] |
| 462 | mod tests { |
| 463 | use super::*; |
| 464 | |
| 465 | #[test] |
| 466 | fn the_token_a_spec_carries_replaces_the_one_it_was_fetched_with() { |
| 467 | let mut api = Api::offline(); |
| 468 | let mut spec = json!({ "job": "job_1", "masks": ["s3cret"], "next_token": "fresh" }); |
| 469 | api.take_next_token(&mut spec); |
| 470 | assert_eq!(api.token, "fresh"); |
| 471 | assert!(spec.get("next_token").is_none(), "the job's steps never see it"); |
| 472 | assert_eq!(spec["masks"], json!(["s3cret", "fresh"])); |
| 473 | // A g1t that does not rotate sends none: the token stays. |
| 474 | let mut spec = json!({ "job": "job_1", "masks": [] }); |
| 475 | api.take_next_token(&mut spec); |
| 476 | assert_eq!(api.token, "fresh"); |
| 477 | assert_eq!(spec["masks"], json!([])); |
| 478 | } |
| 479 | |
| 480 | #[test] |
| 481 | fn every_line_is_stamped_with_the_time_as_github_stamps_it() { |
| 482 | assert_eq!(stamp(UNIX_EPOCH), "1970-01-01T00:00:00.0000000Z"); |
| 483 | assert_eq!(stamp(UNIX_EPOCH + Duration::new(1_791_797_067, 123_456_789)), "2026-10-12T09:24:27.1234567Z"); |
| 484 | // A leap day, and the last day of February in a century that has none. |
| 485 | assert_eq!(stamp(UNIX_EPOCH + Duration::from_secs(951_782_400)), "2000-02-29T00:00:00.0000000Z"); |
| 486 | assert_eq!(stamp(UNIX_EPOCH + Duration::from_secs(4_107_542_399)), "2100-02-28T23:59:59.0000000Z"); |
| 487 | let mut log = log(&["s3cr3t"]); |
| 488 | log.line("one s3cr3t\ntwo"); |
| 489 | let lines: Vec<&str> = log.buffer.lines().collect(); |
| 490 | assert_eq!(lines.len(), 2, "each line of a message is stamped"); |
| 491 | for (line, text) in lines.iter().zip(["one ***", "two"]) { |
| 492 | let (at, rest) = line.split_once(' ').unwrap(); |
| 493 | assert_eq!((at.len(), &at[10..11], &at[27..]), (28, "T", "Z"), "{line}"); |
| 494 | assert_eq!(rest, text); |
| 495 | } |
| 496 | assert_eq!(log.buffered(), "one ***\ntwo\n"); |
| 497 | } |
| 498 | |
| 499 | fn log(secrets: &[&str]) -> Log { |
| 500 | Log::new(Api::offline(), mask::all_variants(secrets.iter().copied())) |
| 501 | } |
| 502 | |
| 503 | /// A server that answers the first `fail` requests with a 500 and the |
| 504 | /// rest with `{}`, and hands back each request's body. |
| 505 | fn flaky_server(fail: usize, requests: usize) -> (String, std::thread::JoinHandle<Vec<Value>>) { |
| 506 | use std::io::{BufRead, BufReader, Read, Write}; |
| 507 | let listener = std::net::TcpListener::bind("127.0.0.1:0").unwrap(); |
| 508 | let base = format!("http://{}", listener.local_addr().unwrap()); |
| 509 | let serving = std::thread::spawn(move || { |
| 510 | let mut bodies = Vec::new(); |
| 511 | for answered in 0..requests { |
| 512 | let (stream, _) = listener.accept().unwrap(); |
| 513 | let mut reader = BufReader::new(stream); |
| 514 | let mut length = 0; |
| 515 | loop { |
| 516 | let mut header = String::new(); |
| 517 | reader.read_line(&mut header).unwrap(); |
| 518 | if header.trim().is_empty() { |
| 519 | break; |
| 520 | } |
| 521 | if let Some((name, value)) = header.split_once(':') |
| 522 | && name.eq_ignore_ascii_case("content-length") |
| 523 | { |
| 524 | length = value.trim().parse().unwrap(); |
| 525 | } |
| 526 | } |
| 527 | let mut body = vec![0; length]; |
| 528 | reader.read_exact(&mut body).unwrap(); |
| 529 | bodies.push(serde_json::from_slice::<Value>(&body).unwrap()); |
| 530 | let status = if answered < fail { "500 Internal Server Error" } else { "200 OK" }; |
| 531 | write!(reader.get_mut(), "HTTP/1.1 {status}\r\nContent-Length: 2\r\nConnection: close\r\n\r\n{{}}").unwrap(); |
| 532 | } |
| 533 | bodies |
| 534 | }); |
| 535 | (base, serving) |
| 536 | } |
| 537 | |
| 538 | #[test] |
| 539 | fn each_batch_of_the_log_keeps_its_number_when_sent_again() { |
| 540 | let (base, serving) = flaky_server(1, 3); |
| 541 | let mut log = Log::new(Api { base, job: "job_1".into(), token: "t".into() }, Vec::new()); |
| 542 | log.line("one"); |
| 543 | log.flush(); |
| 544 | log.line("two"); |
| 545 | log.flush(); |
| 546 | log.flush(); // Nothing waits: no batch, and no number used. |
| 547 | let bodies = serving.join().unwrap(); |
| 548 | let sent: Vec<(u64, String)> = bodies |
| 549 | .iter() |
| 550 | .map(|body| (body["report"]["chunk"].as_u64().unwrap(), unstamped(body["report"]["text"].as_str().unwrap()))) |
| 551 | .collect(); |
| 552 | // The first batch failed and was sent again with its number; the |
| 553 | // next is the job's second. |
| 554 | assert_eq!(sent, [(1, "one\n".into()), (1, "one\n".into()), (2, "two\n".into())]); |
| 555 | assert_eq!(bodies[0], bodies[1], "a batch sent again is the same batch"); |
| 556 | } |
| 557 | |
| 558 | #[test] |
| 559 | fn a_long_wait_says_so_in_the_log_as_it_goes() { |
| 560 | let mut log = log(&[]); |
| 561 | let answer = log.waiting(Duration::from_millis(50), |_| { |
| 562 | std::thread::sleep(Duration::from_millis(180)); |
| 563 | 42 |
| 564 | }, |seconds| format!("still waiting ({seconds}s)")); |
| 565 | assert_eq!(answer, 42); |
| 566 | let lines = log.buffered(); |
| 567 | let told = lines.lines().filter(|line| line.starts_with("still waiting (")).count(); |
| 568 | assert!((2..=4).contains(&told), "a line each time the wait goes on: {lines:?}"); |
| 569 | // A wait that ends at once writes nothing. |
| 570 | let mut quick = super::tests::log(&[]); |
| 571 | assert_eq!(quick.waiting(Duration::from_secs(5), |api| api.job, |_| "never".into()), "job_1"); |
| 572 | assert_eq!(quick.buffered(), ""); |
| 573 | } |
| 574 | |
| 575 | #[test] |
| 576 | fn outputs_holding_a_secret_are_left_out() { |
| 577 | let mut log = log(&["s3cr3t-token"]); |
| 578 | let mut outputs = serde_json::Map::new(); |
| 579 | outputs.insert("version".into(), json!("1.2.0")); |
| 580 | outputs.insert("leak".into(), json!("token=s3cr3t-token")); |
| 581 | outputs.insert("encoded".into(), json!("czNjcjN0LXRva2Vu")); |
| 582 | let kept = log.withhold_secrets(&outputs); |
| 583 | assert_eq!(kept.keys().collect::<Vec<_>>(), ["version"]); |
| 584 | assert!(log.buffer.contains("The output `leak` was left out")); |
| 585 | assert!(log.buffer.contains("The output `encoded` was left out")); |
| 586 | } |
| 587 | |
| 588 | #[test] |
| 589 | fn a_cancelled_answer_is_heard_once_and_taken_in() { |
| 590 | let cancel = Cancel::new(); |
| 591 | cancel.hear(&json!({ "ok": true })); |
| 592 | assert!(!cancel.cancelled()); |
| 593 | cancel.hear(&json!({ "ok": true, "cancelled": true })); |
| 594 | assert!(cancel.cancelled() && cancel.interrupt()); |
| 595 | cancel.take(); |
| 596 | assert!(cancel.cancelled() && !cancel.interrupt(), "cleanup steps are not stopped again"); |
| 597 | cancel.hear(&json!({ "ok": true, "cancelled": false })); |
| 598 | assert!(cancel.cancelled(), "a cancelled job stays cancelled"); |
| 599 | } |
| 600 | |
| 601 | #[test] |
| 602 | fn a_summary_past_its_limit_is_refused_in_the_log() { |
| 603 | let mut log = log(&[]); |
| 604 | log.summary(" |
| 605 | "); |
| 606 | assert!(log.buffer.is_empty(), "an empty summary is not sent"); |
| 607 | log.summary(&"x".repeat(MAX_SUMMARY_BYTES + 1)); |
| 608 | assert!(log.buffer.contains("$GITHUB_STEP_SUMMARY upload aborted")); |
| 609 | assert!(log.buffer.contains("1025k")); |
| 610 | } |
| 611 | |
| 612 | #[test] |
| 613 | fn annotations_carry_their_columns_and_end() { |
| 614 | let log = log(&["hidden"]); |
| 615 | let properties: serde_json::Map<String, Value> = |
| 616 | serde_json::from_value(json!({ "file": "a.rs", "line": "3", "col": "7", "endLine": "4", "endColumn": "2", "title": "t hidden" })).unwrap(); |
| 617 | let report = log.annotation_report("error", "bad hidden", &properties); |
| 618 | assert_eq!(report["line"], 3); |
| 619 | assert_eq!(report["column"], 7); |
| 620 | assert_eq!(report["end_line"], 4); |
| 621 | assert_eq!(report["end_column"], 2); |
| 622 | assert_eq!(report["title"], "t ***"); |
| 623 | assert_eq!(report["message"], "bad ***"); |
| 624 | let bare = log.annotation_report("notice", "x", &serde_json::Map::new()); |
| 625 | assert!(bare["column"].is_null() && bare["file"].is_null()); |
| 626 | } |
| 627 | |
| 628 | #[test] |
| 629 | fn added_masks_cover_every_form() { |
| 630 | let mut log = log(&[]); |
| 631 | log.add_mask("line one\nline two"); |
| 632 | assert_eq!(log.mask("first: line one"), "first: ***"); |
| 633 | assert_eq!(log.mask("then line two"), "then ***"); |
| 634 | // Longest first: the whole value, not its pieces. |
| 635 | log.add_mask("abc"); |
| 636 | log.add_mask("abcdef"); |
| 637 | assert_eq!(log.mask("abcdef"), "***"); |
| 638 | } |
| 639 | } |