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