| 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::collections::VecDeque; |
| 5 | use std::sync::Arc; |
| 6 | use std::sync::atomic::{AtomicBool, Ordering}; |
| 7 | use std::sync::mpsc; |
| 8 | use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; |
| 9 | |
| 10 | use anyhow::Result; |
| 11 | use g1t_actions::mask; |
| 12 | use serde_json::{Value, json}; |
| 13 | |
| 14 | /// How long log lines wait before they are handed to the uploader: about a |
| 15 | /// second, so a running step's page follows it closely, at one write to |
| 16 | /// g1t a second. |
| 17 | const FLUSH_EVERY: Duration = Duration::from_millis(1000); |
| 18 | /// How much log is handed to the uploader at once. |
| 19 | const FLUSH_BYTES: usize = 64 * 1024; |
| 20 | /// The most log the uploader sends in one report, joining the batches that |
| 21 | /// waited while it was sending the last: under the 256 KiB g1t keeps of |
| 22 | /// one (services/actions, `MAX_CHUNK_BYTES`). |
| 23 | const SEND_BYTES: usize = 192 * 1024; |
| 24 | /// How long the job's end waits for its log to reach g1t before the rest |
| 25 | /// is let go and the job's conclusion sent: a slow log never holds a job, |
| 26 | /// or the deploy waiting on it, for longer. |
| 27 | const DRAIN_WAIT: Duration = Duration::from_secs(30); |
| 28 | /// How long, past [`DRAIN_WAIT`], the job's end waits for the report in |
| 29 | /// flight and its conclusion: one report's three tries at most. |
| 30 | const HURRY_WAIT: Duration = Duration::from_secs(100); |
| 31 | /// The most one step may add to the job's summary, as on GitHub. |
| 32 | pub(crate) const MAX_SUMMARY_BYTES: usize = 1024 * 1024; |
| 33 | /// How long the runner goes without a report before it asks whether the |
| 34 | /// job was cancelled. |
| 35 | const PING_EVERY: Duration = Duration::from_secs(10); |
| 36 | |
| 37 | /// Whether the job was cancelled, as g1t's answers to its reports say. |
| 38 | struct Cancel { |
| 39 | /// g1t said so. |
| 40 | said: AtomicBool, |
| 41 | /// The job has taken it in: the step it was on was stopped, and the |
| 42 | /// cleanup steps that follow are not stopped for it again. |
| 43 | taken: AtomicBool, |
| 44 | } |
| 45 | |
| 46 | impl Cancel { |
| 47 | const fn new() -> Cancel { |
| 48 | Cancel { said: AtomicBool::new(false), taken: AtomicBool::new(false) } |
| 49 | } |
| 50 | |
| 51 | /// Reads an answer to a report: `cancelled` when the run was cancelled. |
| 52 | fn hear(&self, answer: &Value) { |
| 53 | if answer["cancelled"].as_bool() == Some(true) { |
| 54 | self.said.store(true, Ordering::Relaxed); |
| 55 | } |
| 56 | } |
| 57 | |
| 58 | fn cancelled(&self) -> bool { |
| 59 | self.said.load(Ordering::Relaxed) |
| 60 | } |
| 61 | |
| 62 | fn interrupt(&self) -> bool { |
| 63 | self.cancelled() && !self.taken.load(Ordering::Relaxed) |
| 64 | } |
| 65 | |
| 66 | fn take(&self) { |
| 67 | self.taken.store(true, Ordering::Relaxed); |
| 68 | } |
| 69 | } |
| 70 | |
| 71 | /// This job's (one runs per process). |
| 72 | static CANCEL: Cancel = Cancel::new(); |
| 73 | |
| 74 | /// Whether g1t said the job was cancelled. |
| 75 | pub(crate) fn cancelled() -> bool { |
| 76 | CANCEL.cancelled() |
| 77 | } |
| 78 | |
| 79 | /// Whether a running step should be stopped: cancelled, and not yet taken in. |
| 80 | pub(crate) fn interrupt() -> bool { |
| 81 | CANCEL.interrupt() |
| 82 | } |
| 83 | |
| 84 | /// The job has seen the cancellation: what runs from here is its cleanup. |
| 85 | pub(crate) fn take_cancel() { |
| 86 | CANCEL.take(); |
| 87 | } |
| 88 | |
| 89 | /// How many times a spec is asked for before the job fails. |
| 90 | const SPEC_TRIES: u32 = 4; |
| 91 | |
| 92 | /// How long to wait before asking for a spec again, after `attempt` tries: |
| 93 | /// 1, 2, then 4 seconds. |
| 94 | fn spec_backoff(attempt: u32) -> Duration { |
| 95 | Duration::from_secs(1 << (attempt - 1).min(2)) |
| 96 | } |
| 97 | |
| 98 | /// Why a spec did not arrive. |
| 99 | #[derive(Debug)] |
| 100 | enum SpecError { |
| 101 | /// g1t answered with this status. |
| 102 | Status(u16), |
| 103 | /// The request could not be made or answered (connection, timeout). |
| 104 | Transport(String), |
| 105 | /// The answer's body did not read as JSON: cut short, usually. |
| 106 | Body(std::io::Error), |
| 107 | } |
| 108 | |
| 109 | impl SpecError { |
| 110 | /// Whether asking again may get the spec: not when g1t said no. |
| 111 | fn worth_retrying(&self) -> bool { |
| 112 | match self { |
| 113 | SpecError::Status(code) => *code >= 500, |
| 114 | SpecError::Transport(_) | SpecError::Body(_) => true, |
| 115 | } |
| 116 | } |
| 117 | } |
| 118 | |
| 119 | impl From<ureq::Error> for SpecError { |
| 120 | fn from(error: ureq::Error) -> Self { |
| 121 | match error { |
| 122 | ureq::Error::Status(code, _) => SpecError::Status(code), |
| 123 | ureq::Error::Transport(transport) => SpecError::Transport(transport.to_string()), |
| 124 | } |
| 125 | } |
| 126 | } |
| 127 | |
| 128 | impl std::fmt::Display for SpecError { |
| 129 | fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { |
| 130 | match self { |
| 131 | SpecError::Status(code) => write!(f, "g1t answered {code}"), |
| 132 | SpecError::Transport(error) => write!(f, "{error}"), |
| 133 | SpecError::Body(error) => write!(f, "Failed to read JSON: {error}"), |
| 134 | } |
| 135 | } |
| 136 | } |
| 137 | |
| 138 | impl std::error::Error for SpecError {} |
| 139 | |
| 140 | #[derive(Clone)] |
| 141 | pub(crate) struct Api { |
| 142 | pub(crate) base: String, |
| 143 | pub(crate) job: String, |
| 144 | pub(crate) token: String, |
| 145 | } |
| 146 | |
| 147 | impl Api { |
| 148 | /// The job's spec. With `rotate`, g1t spends the token it was asked |
| 149 | /// with and sends a new one beside the spec, which this takes for |
| 150 | /// everything after (`next_token`): a copy of the first left on the |
| 151 | /// runner's computer cannot fetch the job, its secrets or a G1T_TOKEN |
| 152 | /// again. A g1t that predates it sends none, and the token stays. |
| 153 | /// |
| 154 | /// With `broker`, this harness passes its job's requests to brokered |
| 155 | /// secrets' hosts through g1t (broker.rs), and the spec lists each |
| 156 | /// stand-in's hosts (`brokered`). |
| 157 | /// |
| 158 | /// A spec that does not arrive whole (the connection drops, or the body |
| 159 | /// ends early) or that g1t could not make (5xx) is asked for again, up |
| 160 | /// to [`SPEC_TRIES`] times: Deploy #449's job failed on one truncated |
| 161 | /// answer. Not with `rotate`: g1t spends the token on the first ask, |
| 162 | /// whether or not the answer arrived, so a second would be refused. |
| 163 | pub(crate) fn spec(&mut self, rotate: bool, broker: bool) -> Result<Value> { |
| 164 | let mut body = json!({ "token": self.token }); |
| 165 | if rotate { |
| 166 | body["rotate"] = json!(true); |
| 167 | } |
| 168 | if broker { |
| 169 | body["broker"] = json!(true); |
| 170 | } |
| 171 | let url = format!("{}/actions/jobs/{}/spec", self.base, self.job); |
| 172 | let tries = if rotate { 1 } else { SPEC_TRIES }; |
| 173 | let mut attempt = 1; |
| 174 | let mut spec: Value = loop { |
| 175 | let fetched = crate::http::agent().post(&url) |
| 176 | .timeout(Duration::from_secs(60)) |
| 177 | .send_json(body.clone()) |
| 178 | .map_err(SpecError::from) |
| 179 | .and_then(|response| response.into_json::<Value>().map_err(SpecError::Body)); |
| 180 | match fetched { |
| 181 | Ok(spec) => break spec, |
| 182 | Err(error) if attempt < tries && error.worth_retrying() => { |
| 183 | eprintln!("g1t-runner: the job's spec did not arrive whole ({error}); asking again"); |
| 184 | std::thread::sleep(spec_backoff(attempt)); |
| 185 | attempt += 1; |
| 186 | } |
| 187 | Err(error) => return Err(error.into()), |
| 188 | } |
| 189 | }; |
| 190 | self.take_next_token(&mut spec); |
| 191 | Ok(spec) |
| 192 | } |
| 193 | |
| 194 | /// Takes the token a spec carries in place of the one it was fetched |
| 195 | /// with, and masks it in the log. |
| 196 | fn take_next_token(&mut self, spec: &mut Value) { |
| 197 | let next = spec.as_object_mut().and_then(|s| s.remove("next_token").or_else(|| s.remove("nextToken"))); |
| 198 | if let Some(next) = next.as_ref().and_then(Value::as_str).filter(|t| !t.is_empty()) { |
| 199 | self.token = next.to_owned(); |
| 200 | if let Some(masks) = spec.get_mut("masks").and_then(Value::as_array_mut) { |
| 201 | masks.push(json!(next)); |
| 202 | } |
| 203 | } |
| 204 | } |
| 205 | |
| 206 | /// Where to fetch another repository's action from: `{"source": "g1t", |
| 207 | /// "url", "ref", "token"}`, or `{"source": "github", "sha", "archive", |
| 208 | /// "note"}`: the commit GitHub's ref names, and whether g1t keeps its |
| 209 | /// archive (`action_archive`). Err holds why g1t |
| 210 | /// refused (`true`: the repository is private and may not be used |
| 211 | /// here), or that it could not be asked (`false`). |
| 212 | pub(crate) fn action(&self, repository: &str, git_ref: &str) -> std::result::Result<Value, (bool, String)> { |
| 213 | // The first job to use an action at a commit waits while g1t |
| 214 | // fetches and keeps its archive. |
| 215 | let sent = crate::http::agent().post(&format!("{}/actions/jobs/{}/action", self.base, self.job)) |
| 216 | .timeout(Duration::from_secs(120)) |
| 217 | .send_json(json!({ "token": self.token, "report": { "repository": repository, "ref": git_ref } })); |
| 218 | match sent { |
| 219 | Ok(response) => response.into_json().map_err(|error| (false, error.to_string())), |
| 220 | Err(ureq::Error::Status(code, response)) => { |
| 221 | let body: Value = response.into_json().unwrap_or(Value::Null); |
| 222 | let message = body["error"]["message"].as_str().unwrap_or("g1t did not answer.").to_owned(); |
| 223 | Err((code == 403, message)) |
| 224 | } |
| 225 | Err(error) => Err((false, error.to_string())), |
| 226 | } |
| 227 | } |
| 228 | |
| 229 | /// Downloads the archive g1t keeps of `repository` at `sha` to `to`. |
| 230 | pub(crate) fn action_archive(&self, repository: &str, sha: &str, to: &std::path::Path) -> std::result::Result<u64, String> { |
| 231 | let response = crate::http::agent().post(&format!("{}/actions/jobs/{}/archive", self.base, self.job)) |
| 232 | .timeout(Duration::from_secs(300)) |
| 233 | .send_json(json!({ "token": self.token, "report": { "repository": repository, "sha": sha } })) |
| 234 | .map_err(|error| match error { |
| 235 | ureq::Error::Status(code, response) => { |
| 236 | let body: Value = response.into_json().unwrap_or(Value::Null); |
| 237 | body["error"]["message"].as_str().map_or_else(|| format!("g1t answered {code}"), str::to_owned) |
| 238 | } |
| 239 | other => other.to_string(), |
| 240 | })?; |
| 241 | let mut file = std::fs::File::create(to).map_err(|error| error.to_string())?; |
| 242 | std::io::copy(&mut response.into_reader(), &mut file).map_err(|error| error.to_string()) |
| 243 | } |
| 244 | |
| 245 | /// An API with no address, which sends nothing: what the tests use, so |
| 246 | /// a step's run is not held up by reports that go nowhere (each one |
| 247 | /// tried three times, with waits between, over a second and a half). |
| 248 | #[cfg(test)] |
| 249 | pub(crate) fn offline() -> Api { |
| 250 | Api { base: String::new(), job: "job_1".into(), token: "t".into() } |
| 251 | } |
| 252 | |
| 253 | pub(crate) fn report(&self, report: Value) { |
| 254 | // No address: nowhere to send it (Api::offline). |
| 255 | if self.base.is_empty() { |
| 256 | return; |
| 257 | } |
| 258 | // A report that cannot be sent is tried a few times, then dropped: |
| 259 | // the job goes on, and g1t notices a silent job by itself. |
| 260 | for attempt in 0..3 { |
| 261 | let sent = crate::http::agent().post(&format!("{}/actions/jobs/{}", self.base, self.job)) |
| 262 | .timeout(Duration::from_secs(30)) |
| 263 | .send_json(json!({ "token": self.token, "report": report })); |
| 264 | match sent { |
| 265 | Ok(response) => { |
| 266 | if let Ok(answer) = response.into_json::<Value>() { |
| 267 | CANCEL.hear(&answer); |
| 268 | } |
| 269 | return; |
| 270 | } |
| 271 | // Refused: the job was cancelled or finished; nothing to retry. |
| 272 | Err(ureq::Error::Status(code, _)) if (400..500).contains(&code) => return, |
| 273 | Err(_) => std::thread::sleep(Duration::from_millis(500 * (attempt + 1))), |
| 274 | } |
| 275 | } |
| 276 | } |
| 277 | } |
| 278 | |
| 279 | /// What the log hands its uploader. |
| 280 | enum Outgoing { |
| 281 | /// A batch of step `.0`'s log. |
| 282 | Log(u32, String), |
| 283 | /// A report about the job (its steps, an annotation, a summary, a |
| 284 | /// ping), sent ahead of any log still waiting. |
| 285 | Report(Value), |
| 286 | /// The job's conclusion, sent once everything before it has been. |
| 287 | Done(Value), |
| 288 | /// Answered once everything handed over before it has been sent. |
| 289 | #[cfg(test)] |
| 290 | Settled(mpsc::Sender<()>), |
| 291 | } |
| 292 | |
| 293 | /// Sends the job's reports to g1t on a thread of its own, so a step never |
| 294 | /// waits on one. Each report used to be sent where it was made, and a step |
| 295 | /// that printed quickly to a g1t that took a second to answer waited that |
| 296 | /// second for every line (the batch's second had passed again by the time |
| 297 | /// the last one was answered): Deploy #511's and #531's builds, done in a |
| 298 | /// minute or two, sent their output a line a second for twenty minutes, |
| 299 | /// and held their deploys. Here what waits while one report is sent goes |
| 300 | /// in the next together. |
| 301 | struct Uploader { |
| 302 | api: Api, |
| 303 | /// Log batches waiting, in order. |
| 304 | logs: VecDeque<(u32, String)>, |
| 305 | /// Other reports waiting, in order. |
| 306 | others: VecDeque<Value>, |
| 307 | done: Option<Value>, |
| 308 | /// Whether the log can still hand anything over. |
| 309 | open: bool, |
| 310 | /// Set when the job's end has waited long enough for the log: what |
| 311 | /// waits of it is let go, and the conclusion sent. |
| 312 | hurry: Arc<AtomicBool>, |
| 313 | /// The number of the last batch sent, 1 for the job's first: each |
| 314 | /// batch carries its own, and keeps it when it is sent again, so g1t |
| 315 | /// keeps a batch it already has once. |
| 316 | chunk: u64, |
| 317 | #[cfg(test)] |
| 318 | settled: Vec<mpsc::Sender<()>>, |
| 319 | } |
| 320 | |
| 321 | impl Uploader { |
| 322 | fn take(&mut self, item: Outgoing) { |
| 323 | match item { |
| 324 | Outgoing::Log(step, text) => self.logs.push_back((step, text)), |
| 325 | Outgoing::Report(report) => self.others.push_back(report), |
| 326 | Outgoing::Done(report) => self.done = Some(report), |
| 327 | #[cfg(test)] |
| 328 | Outgoing::Settled(answer) => self.settled.push(answer), |
| 329 | } |
| 330 | } |
| 331 | |
| 332 | /// Sends everything handed over, until the log is closed and nothing |
| 333 | /// waits; the conclusion last. |
| 334 | fn run(mut self, queue: mpsc::Receiver<Outgoing>) { |
| 335 | loop { |
| 336 | if self.logs.is_empty() && self.others.is_empty() { |
| 337 | #[cfg(test)] |
| 338 | for answer in self.settled.drain(..) { |
| 339 | let _ = answer.send(()); |
| 340 | } |
| 341 | if !self.open { |
| 342 | if let Some(done) = self.done.take() { |
| 343 | self.api.report(done); |
| 344 | } |
| 345 | return; |
| 346 | } |
| 347 | match queue.recv() { |
| 348 | Ok(item) => self.take(item), |
| 349 | Err(_) => self.open = false, |
| 350 | } |
| 351 | continue; |
| 352 | } |
| 353 | // Everything that waits, so the batches go together. |
| 354 | while self.open { |
| 355 | match queue.try_recv() { |
| 356 | Ok(item) => self.take(item), |
| 357 | Err(mpsc::TryRecvError::Empty) => break, |
| 358 | Err(mpsc::TryRecvError::Disconnected) => self.open = false, |
| 359 | } |
| 360 | } |
| 361 | if self.hurry.load(Ordering::Relaxed) && !self.logs.is_empty() { |
| 362 | let left: usize = self.logs.drain(..).map(|(_, text)| text.len()).sum(); |
| 363 | eprintln!( |
| 364 | "g1t-runner: {left} bytes of the job's log did not reach g1t in time and were let go" |
| 365 | ); |
| 366 | } |
| 367 | if let Some(report) = self.others.pop_front() { |
| 368 | self.api.report(report); |
| 369 | } else if let Some(report) = self.next_batch() { |
| 370 | self.api.report(report); |
| 371 | } |
| 372 | } |
| 373 | } |
| 374 | |
| 375 | /// The batches that wait for the same step, joined up to |
| 376 | /// [`SEND_BYTES`], numbered. |
| 377 | fn next_batch(&mut self) -> Option<Value> { |
| 378 | let (step, mut text) = self.logs.pop_front()?; |
| 379 | while let Some((next, more)) = self.logs.front() |
| 380 | && *next == step |
| 381 | && text.len() + more.len() <= SEND_BYTES |
| 382 | { |
| 383 | text.push_str(more); |
| 384 | self.logs.pop_front(); |
| 385 | } |
| 386 | self.chunk += 1; |
| 387 | Some(json!({ "kind": "log", "step": step, "chunk": self.chunk, "text": text })) |
| 388 | } |
| 389 | } |
| 390 | |
| 391 | /// The job's log, masked, sent in batches. `masks` holds every form of |
| 392 | /// every secret (`g1t_actions::mask`), longest first. |
| 393 | pub(crate) struct Log { |
| 394 | pub(crate) api: Api, |
| 395 | pub(crate) masks: Vec<String>, |
| 396 | step: u32, |
| 397 | buffer: String, |
| 398 | last: Instant, |
| 399 | /// When anything was last sent, for the ping. |
| 400 | sent: Instant, |
| 401 | /// The problem matchers steps added, which last the whole job. |
| 402 | pub(crate) matchers: super::matchers::Matchers, |
| 403 | /// Where reports go to be sent (`Uploader`), until the job's end. |
| 404 | queue: Option<mpsc::Sender<Outgoing>>, |
| 405 | /// Hangs up when the uploader has finished. |
| 406 | uploaded: Option<mpsc::Receiver<()>>, |
| 407 | hurry: Arc<AtomicBool>, |
| 408 | /// Everything sent so far, so a test reads the whole log however its |
| 409 | /// batches fell (`buffered`). |
| 410 | #[cfg(test)] |
| 411 | flushed: String, |
| 412 | } |
| 413 | |
| 414 | impl Log { |
| 415 | pub(crate) fn new(api: Api, mut masks: Vec<String>) -> Log { |
| 416 | masks.retain(|mask| !mask.is_empty()); |
| 417 | masks.sort_by_key(|mask| std::cmp::Reverse(mask.len())); |
| 418 | let (queue, handed) = mpsc::channel(); |
| 419 | let (finished, uploaded) = mpsc::channel::<()>(); |
| 420 | let hurry = Arc::new(AtomicBool::new(false)); |
| 421 | let uploader = Uploader { |
| 422 | api: api.clone(), |
| 423 | logs: VecDeque::new(), |
| 424 | others: VecDeque::new(), |
| 425 | done: None, |
| 426 | open: true, |
| 427 | hurry: hurry.clone(), |
| 428 | chunk: 0, |
| 429 | #[cfg(test)] |
| 430 | settled: Vec::new(), |
| 431 | }; |
| 432 | std::thread::spawn(move || { |
| 433 | uploader.run(handed); |
| 434 | drop(finished); |
| 435 | }); |
| 436 | Log { |
| 437 | api, |
| 438 | masks, |
| 439 | step: 0, |
| 440 | buffer: String::new(), |
| 441 | last: Instant::now(), |
| 442 | sent: Instant::now(), |
| 443 | matchers: super::matchers::Matchers::default(), |
| 444 | queue: Some(queue), |
| 445 | uploaded: Some(uploaded), |
| 446 | hurry, |
| 447 | #[cfg(test)] |
| 448 | flushed: String::new(), |
| 449 | } |
| 450 | } |
| 451 | |
| 452 | /// Hands `item` to the uploader; nothing, once the job has ended. |
| 453 | fn send(&self, item: Outgoing) { |
| 454 | if let Some(queue) = &self.queue { |
| 455 | let _ = queue.send(item); |
| 456 | } |
| 457 | } |
| 458 | |
| 459 | /// Waits for everything handed over to be sent: up to `within`, then |
| 460 | /// lets the log that still waits go, and waits for the report in flight |
| 461 | /// and the conclusion. |
| 462 | fn finish(&mut self, within: Duration) { |
| 463 | self.flush(); |
| 464 | self.queue = None; |
| 465 | let Some(uploaded) = self.uploaded.take() else { |
| 466 | return; |
| 467 | }; |
| 468 | if let Err(mpsc::RecvTimeoutError::Timeout) = uploaded.recv_timeout(within) { |
| 469 | self.hurry.store(true, Ordering::Relaxed); |
| 470 | let _ = uploaded.recv_timeout(HURRY_WAIT); |
| 471 | } |
| 472 | } |
| 473 | |
| 474 | /// Waits until everything handed over so far has been sent. |
| 475 | #[cfg(test)] |
| 476 | fn settle(&self) { |
| 477 | let (answer, settled) = mpsc::channel(); |
| 478 | self.send(Outgoing::Settled(answer)); |
| 479 | let _ = settled.recv_timeout(Duration::from_secs(60)); |
| 480 | } |
| 481 | |
| 482 | /// The log so far, what was sent and what waits to be, without the |
| 483 | /// time each line is stamped with. |
| 484 | #[cfg(test)] |
| 485 | pub(crate) fn buffered(&self) -> String { |
| 486 | unstamped(&format!("{}{}", self.flushed, self.buffer)) |
| 487 | } |
| 488 | |
| 489 | /// Starts writing to step `number` (0 for the job's setup). |
| 490 | pub(crate) fn step(&mut self, number: u32) { |
| 491 | self.flush(); |
| 492 | self.step = number; |
| 493 | } |
| 494 | |
| 495 | pub(crate) fn mask(&self, text: &str) -> String { |
| 496 | mask::apply(text, &self.masks) |
| 497 | } |
| 498 | |
| 499 | /// `::add-mask::`: masks `value` from here on, in every form it can |
| 500 | /// take (each line, base64, JSON-escaped), as a secret is. |
| 501 | pub(crate) fn add_mask(&mut self, value: &str) { |
| 502 | let mut added = false; |
| 503 | for variant in mask::variants(value) { |
| 504 | if !self.masks.contains(&variant) { |
| 505 | self.masks.push(variant); |
| 506 | added = true; |
| 507 | } |
| 508 | } |
| 509 | if added { |
| 510 | self.masks.sort_by_key(|mask| std::cmp::Reverse(mask.len())); |
| 511 | } |
| 512 | } |
| 513 | |
| 514 | /// Adds a line to the log, masked, each of its lines stamped with the |
| 515 | /// time, as GitHub's runner writes its logs |
| 516 | /// (`2026-10-12T09:41:07.1234567Z text`). |
| 517 | pub(crate) fn line(&mut self, text: &str) { |
| 518 | let masked = self.mask(text); |
| 519 | let at = stamp(SystemTime::now()); |
| 520 | for line in masked.split('\n') { |
| 521 | self.buffer.push_str(&at); |
| 522 | self.buffer.push(' '); |
| 523 | self.buffer.push_str(line); |
| 524 | self.buffer.push('\n'); |
| 525 | } |
| 526 | if self.buffer.len() >= FLUSH_BYTES || self.last.elapsed() >= FLUSH_EVERY { |
| 527 | self.flush(); |
| 528 | } |
| 529 | } |
| 530 | |
| 531 | /// Sends what is waiting if it has waited long enough, and asks after |
| 532 | /// the job when nothing has been sent for a while, so a cancellation |
| 533 | /// reaches a step that prints nothing. |
| 534 | pub(crate) fn tick(&mut self) { |
| 535 | if !self.buffer.is_empty() && self.last.elapsed() >= FLUSH_EVERY { |
| 536 | self.flush(); |
| 537 | } else if self.sent.elapsed() >= PING_EVERY { |
| 538 | self.sent = Instant::now(); |
| 539 | self.send(Outgoing::Report(json!({ "kind": "ping" }))); |
| 540 | } |
| 541 | } |
| 542 | |
| 543 | /// Hands what waits to the uploader, which sends it as soon as it can. |
| 544 | pub(crate) fn flush(&mut self) { |
| 545 | self.last = Instant::now(); |
| 546 | if self.buffer.is_empty() { |
| 547 | return; |
| 548 | } |
| 549 | self.sent = Instant::now(); |
| 550 | let text = std::mem::take(&mut self.buffer); |
| 551 | #[cfg(test)] |
| 552 | self.flushed.push_str(&text); |
| 553 | self.send(Outgoing::Log(self.step, text)); |
| 554 | } |
| 555 | |
| 556 | /// Does `work` with the job's API on a thread of its own, writing |
| 557 | /// `waiting(seconds)` to the log, and sending it, every `every` it is |
| 558 | /// still going: a wait the job's page would otherwise show as a silent |
| 559 | /// log, such as g1t fetching an action's archive from GitHub. |
| 560 | pub(crate) fn waiting<T: Send + 'static>( |
| 561 | &mut self, |
| 562 | every: Duration, |
| 563 | work: impl FnOnce(Api) -> T + Send + 'static, |
| 564 | waiting: impl Fn(u64) -> String, |
| 565 | ) -> T { |
| 566 | self.flush(); |
| 567 | let api = self.api.clone(); |
| 568 | let (done, answer) = std::sync::mpsc::channel(); |
| 569 | let worker = std::thread::spawn(move || { |
| 570 | let _ = done.send(work(api)); |
| 571 | }); |
| 572 | let started = Instant::now(); |
| 573 | let result = loop { |
| 574 | match answer.recv_timeout(every) { |
| 575 | Ok(result) => break result, |
| 576 | Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { |
| 577 | self.line(&waiting(started.elapsed().as_secs())); |
| 578 | self.flush(); |
| 579 | } |
| 580 | // The work panicked: so does the job, as it would have. |
| 581 | Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => match worker.join() { |
| 582 | Err(panic) => std::panic::resume_unwind(panic), |
| 583 | Ok(()) => unreachable!("the work sends its result before it ends"), |
| 584 | }, |
| 585 | } |
| 586 | }; |
| 587 | let _ = worker.join(); |
| 588 | result |
| 589 | } |
| 590 | |
| 591 | pub(crate) fn steps(&self, names: &[String]) { |
| 592 | self.send(Outgoing::Report(json!({ "kind": "steps", "steps": names }))); |
| 593 | } |
| 594 | |
| 595 | /// A step's state, sent ahead of any of its log still waiting: a step |
| 596 | /// ends when its process does, and its log catches up after. |
| 597 | pub(crate) fn step_state(&mut self, number: u32, name: &str, status: &str, conclusion: Option<&str>) { |
| 598 | self.flush(); |
| 599 | let name = self.mask(name); |
| 600 | self.send(Outgoing::Report(json!({ "kind": "step", "number": number, "name": name, "status": status, "conclusion": conclusion }))); |
| 601 | } |
| 602 | |
| 603 | /// What a step wrote to `$GITHUB_STEP_SUMMARY`, masked, for the run's |
| 604 | /// page. More than 1 MiB is refused, as on GitHub, with an error in the |
| 605 | /// log. |
| 606 | pub(crate) fn summary(&mut self, markdown: &str) { |
| 607 | if markdown.trim().is_empty() { |
| 608 | return; |
| 609 | } |
| 610 | if markdown.len() > MAX_SUMMARY_BYTES { |
| 611 | self.line(&format!( |
| 612 | "##[error]$GITHUB_STEP_SUMMARY upload aborted: a step's summary may be up to 1024k, and this one is {}k.", |
| 613 | markdown.len().div_ceil(1024) |
| 614 | )); |
| 615 | return; |
| 616 | } |
| 617 | let markdown = self.mask(markdown); |
| 618 | self.flush(); |
| 619 | self.send(Outgoing::Report(json!({ "kind": "summary", "step": self.step, "markdown": markdown }))); |
| 620 | } |
| 621 | |
| 622 | /// An annotation, from `::error::` and its kin or a problem matcher: |
| 623 | /// its `file`, `line`, `col`, `endLine` and `endColumn` as GitHub's |
| 624 | /// commands spell them, sent as `file`, `line`, `column`, `end_line` |
| 625 | /// and `end_column`. |
| 626 | pub(crate) fn annotation(&mut self, level: &str, message: &str, properties: &serde_json::Map<String, Value>) { |
| 627 | let report = self.annotation_report(level, message, properties); |
| 628 | self.send(Outgoing::Report(report)); |
| 629 | } |
| 630 | |
| 631 | fn annotation_report(&self, level: &str, message: &str, properties: &serde_json::Map<String, Value>) -> Value { |
| 632 | let message = self.mask(message); |
| 633 | let title = properties.get("title").and_then(Value::as_str).map(|title| self.mask(title)); |
| 634 | 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()); |
| 635 | json!({ |
| 636 | "kind": "annotation", |
| 637 | "level": level, |
| 638 | "message": message, |
| 639 | "title": title, |
| 640 | "file": properties.get("file"), |
| 641 | "line": number(&["line"]), |
| 642 | "column": number(&["col"]), |
| 643 | "end_line": number(&["endLine"]), |
| 644 | "end_column": number(&["endColumn"]), |
| 645 | }) |
| 646 | } |
| 647 | |
| 648 | /// The job's conclusion, sent after its log (g1t takes no more once the |
| 649 | /// job is done), waiting for that up to [`DRAIN_WAIT`]. |
| 650 | pub(crate) fn done(&mut self, conclusion: &str, outputs: &serde_json::Map<String, Value>, reason: Option<&str>) { |
| 651 | self.done_within(conclusion, outputs, reason, DRAIN_WAIT); |
| 652 | } |
| 653 | |
| 654 | fn done_within( |
| 655 | &mut self, |
| 656 | conclusion: &str, |
| 657 | outputs: &serde_json::Map<String, Value>, |
| 658 | reason: Option<&str>, |
| 659 | within: Duration, |
| 660 | ) { |
| 661 | let outputs = self.withhold_secrets(outputs); |
| 662 | self.flush(); |
| 663 | self.send(Outgoing::Done(json!({ "kind": "done", "conclusion": conclusion, "outputs": outputs, "reason": reason }))); |
| 664 | self.finish(within); |
| 665 | } |
| 666 | |
| 667 | /// The job's outputs without any that hold a secret, as on GitHub: an |
| 668 | /// output goes to other jobs and to the run's page, where no mask |
| 669 | /// reaches. Each one left out is warned of in the log. |
| 670 | pub(crate) fn withhold_secrets(&mut self, outputs: &serde_json::Map<String, Value>) -> serde_json::Map<String, Value> { |
| 671 | let mut kept = serde_json::Map::new(); |
| 672 | for (name, value) in outputs { |
| 673 | let text = match value { |
| 674 | Value::String(text) => text.clone(), |
| 675 | other => other.to_string(), |
| 676 | }; |
| 677 | if mask::reveals(&text, &self.masks) { |
| 678 | self.line(&format!("##[warning]The output `{name}` was left out: it holds a secret.")); |
| 679 | continue; |
| 680 | } |
| 681 | kept.insert(name.clone(), value.clone()); |
| 682 | } |
| 683 | kept |
| 684 | } |
| 685 | } |
| 686 | |
| 687 | /// A log dropped before the job's end (its setup failed) still sends what |
| 688 | /// it was handed. |
| 689 | impl Drop for Log { |
| 690 | fn drop(&mut self) { |
| 691 | self.finish(DRAIN_WAIT); |
| 692 | } |
| 693 | } |
| 694 | |
| 695 | /// A time as GitHub's logs stamp each line: RFC 3339 in UTC, to a tenth |
| 696 | /// of a microsecond (`2026-10-12T09:41:07.1234567Z`). |
| 697 | pub(crate) fn stamp(at: SystemTime) -> String { |
| 698 | let since = at.duration_since(UNIX_EPOCH).unwrap_or_default(); |
| 699 | let seconds = since.as_secs(); |
| 700 | let (days, rest) = (seconds / 86_400, seconds % 86_400); |
| 701 | let (year, month, day) = civil(days as i64); |
| 702 | format!( |
| 703 | "{year:04}-{month:02}-{day:02}T{:02}:{:02}:{:02}.{:07}Z", |
| 704 | rest / 3600, |
| 705 | rest % 3600 / 60, |
| 706 | rest % 60, |
| 707 | since.subsec_nanos() / 100 |
| 708 | ) |
| 709 | } |
| 710 | |
| 711 | /// The calendar date `days` after 1970-01-01 (Howard Hinnant's |
| 712 | /// `civil_from_days`). |
| 713 | fn civil(days: i64) -> (i64, u32, u32) { |
| 714 | let z = days + 719_468; |
| 715 | let era = z.div_euclid(146_097); |
| 716 | let doe = z.rem_euclid(146_097); |
| 717 | let yoe = (doe - doe / 1460 + doe / 36_524 - doe / 146_096) / 365; |
| 718 | let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); |
| 719 | let mp = (5 * doy + 2) / 153; |
| 720 | let day = (doy - (153 * mp + 2) / 5 + 1) as u32; |
| 721 | let month = (if mp < 10 { mp + 3 } else { mp - 9 }) as u32; |
| 722 | let year = yoe + era * 400 + i64::from(month <= 2); |
| 723 | (year, month, day) |
| 724 | } |
| 725 | |
| 726 | /// A log without the time stamped at the start of each line. |
| 727 | #[cfg(test)] |
| 728 | pub(crate) fn unstamped(text: &str) -> String { |
| 729 | text.split_inclusive('\n') |
| 730 | .map(|line| match line.split_once(' ') { |
| 731 | Some((at, rest)) if at.len() == 28 && at.ends_with('Z') && at.as_bytes()[10] == b'T' => rest, |
| 732 | _ => line, |
| 733 | }) |
| 734 | .collect() |
| 735 | } |
| 736 | |
| 737 | #[cfg(test)] |
| 738 | mod tests { |
| 739 | use super::*; |
| 740 | |
| 741 | /// A g1t on 127.0.0.1 that answers each spec request with the next of |
| 742 | /// `answers` (a body, and whether to cut it short), counting the asks. |
| 743 | fn serve(answers: Vec<(&'static str, bool)>) -> (String, std::sync::Arc<std::sync::atomic::AtomicUsize>) { |
| 744 | use std::io::{Read, Write}; |
| 745 | let listener = std::net::TcpListener::bind("127.0.0.1:0").unwrap(); |
| 746 | let base = format!("http://{}", listener.local_addr().unwrap()); |
| 747 | let asked = std::sync::Arc::new(std::sync::atomic::AtomicUsize::new(0)); |
| 748 | let count = asked.clone(); |
| 749 | std::thread::spawn(move || { |
| 750 | for (body, cut) in answers { |
| 751 | let Ok((mut stream, _)) = listener.accept() else { return }; |
| 752 | // The whole request, body and all: hanging up on a body not |
| 753 | // yet read resets the connection on Windows, and the client |
| 754 | // then sees no answer at all, cut short or whole. |
| 755 | let mut request = Vec::new(); |
| 756 | let mut chunk = [0u8; 4096]; |
| 757 | loop { |
| 758 | let Ok(read) = stream.read(&mut chunk) else { break }; |
| 759 | if read == 0 { |
| 760 | break; |
| 761 | } |
| 762 | request.extend_from_slice(&chunk[..read]); |
| 763 | let text = String::from_utf8_lossy(&request); |
| 764 | if let Some(end) = text.find("\r\n\r\n") { |
| 765 | let length = text[..end] |
| 766 | .lines() |
| 767 | .find_map(|line| line.to_ascii_lowercase().strip_prefix("content-length:").map(|n| n.trim().parse::<usize>().unwrap_or(0))) |
| 768 | .unwrap_or(0); |
| 769 | if request.len() >= end + 4 + length { |
| 770 | break; |
| 771 | } |
| 772 | } |
| 773 | } |
| 774 | count.fetch_add(1, Ordering::SeqCst); |
| 775 | // Cut short: says the whole length, sends half, and hangs up. |
| 776 | let sent = if cut { &body[..body.len() / 2] } else { body }; |
| 777 | let head = format!("HTTP/1.1 200 OK\r\nContent-Type: application/json\r\nContent-Length: {}\r\nConnection: close\r\n\r\n", body.len()); |
| 778 | let _ = stream.write_all(head.as_bytes()); |
| 779 | let _ = stream.write_all(sent.as_bytes()); |
| 780 | } |
| 781 | }); |
| 782 | (base, asked) |
| 783 | } |
| 784 | |
| 785 | #[test] |
| 786 | fn a_spec_cut_short_is_asked_for_again() { |
| 787 | let body = r#"{"job":"job_1","masks":[],"steps":[{"run":"cargo test"}]}"#; |
| 788 | let (base, asked) = serve(vec![(body, true), (body, false)]); |
| 789 | let mut api = Api { base, job: "job_1".into(), token: "t".into() }; |
| 790 | let spec = api.spec(false, false).unwrap(); |
| 791 | assert_eq!(spec["steps"][0]["run"], "cargo test"); |
| 792 | assert_eq!(asked.load(Ordering::SeqCst), 2); |
| 793 | } |
| 794 | |
| 795 | #[test] |
| 796 | fn a_spec_that_spends_its_token_is_asked_for_once() { |
| 797 | let body = r#"{"job":"job_1","masks":[],"next_token":"fresh"}"#; |
| 798 | let (base, asked) = serve(vec![(body, true), (body, false)]); |
| 799 | let mut api = Api { base, job: "job_1".into(), token: "t".into() }; |
| 800 | let error = api.spec(true, false).unwrap_err().to_string(); |
| 801 | assert!(error.starts_with("Failed to read JSON"), "{error}"); |
| 802 | assert_eq!(asked.load(Ordering::SeqCst), 1); |
| 803 | } |
| 804 | |
| 805 | #[test] |
| 806 | fn only_what_may_arrive_next_time_is_asked_again() { |
| 807 | assert!(SpecError::Status(502).worth_retrying()); |
| 808 | assert!(!SpecError::Status(403).worth_retrying()); |
| 809 | assert!(!SpecError::Status(404).worth_retrying()); |
| 810 | assert!(SpecError::Transport("connection reset".into()).worth_retrying()); |
| 811 | assert_eq!((spec_backoff(1), spec_backoff(2), spec_backoff(3)), (Duration::from_secs(1), Duration::from_secs(2), Duration::from_secs(4))); |
| 812 | } |
| 813 | |
| 814 | #[test] |
| 815 | fn the_token_a_spec_carries_replaces_the_one_it_was_fetched_with() { |
| 816 | let mut api = Api::offline(); |
| 817 | let mut spec = json!({ "job": "job_1", "masks": ["s3cret"], "next_token": "fresh" }); |
| 818 | api.take_next_token(&mut spec); |
| 819 | assert_eq!(api.token, "fresh"); |
| 820 | assert!(spec.get("next_token").is_none(), "the job's steps never see it"); |
| 821 | assert_eq!(spec["masks"], json!(["s3cret", "fresh"])); |
| 822 | // A g1t that does not rotate sends none: the token stays. |
| 823 | let mut spec = json!({ "job": "job_1", "masks": [] }); |
| 824 | api.take_next_token(&mut spec); |
| 825 | assert_eq!(api.token, "fresh"); |
| 826 | assert_eq!(spec["masks"], json!([])); |
| 827 | } |
| 828 | |
| 829 | #[test] |
| 830 | fn every_line_is_stamped_with_the_time_as_github_stamps_it() { |
| 831 | assert_eq!(stamp(UNIX_EPOCH), "1970-01-01T00:00:00.0000000Z"); |
| 832 | assert_eq!(stamp(UNIX_EPOCH + Duration::new(1_791_797_067, 123_456_789)), "2026-10-12T09:24:27.1234567Z"); |
| 833 | // A leap day, and the last day of February in a century that has none. |
| 834 | assert_eq!(stamp(UNIX_EPOCH + Duration::from_secs(951_782_400)), "2000-02-29T00:00:00.0000000Z"); |
| 835 | assert_eq!(stamp(UNIX_EPOCH + Duration::from_secs(4_107_542_399)), "2100-02-28T23:59:59.0000000Z"); |
| 836 | let mut log = log(&["s3cr3t"]); |
| 837 | log.line("one s3cr3t\ntwo"); |
| 838 | let lines: Vec<&str> = log.buffer.lines().collect(); |
| 839 | assert_eq!(lines.len(), 2, "each line of a message is stamped"); |
| 840 | for (line, text) in lines.iter().zip(["one ***", "two"]) { |
| 841 | let (at, rest) = line.split_once(' ').unwrap(); |
| 842 | assert_eq!((at.len(), &at[10..11], &at[27..]), (28, "T", "Z"), "{line}"); |
| 843 | assert_eq!(rest, text); |
| 844 | } |
| 845 | assert_eq!(log.buffered(), "one ***\ntwo\n"); |
| 846 | } |
| 847 | |
| 848 | fn log(secrets: &[&str]) -> Log { |
| 849 | Log::new(Api::offline(), mask::all_variants(secrets.iter().copied())) |
| 850 | } |
| 851 | |
| 852 | /// A server that answers the first `fail` requests with a 500 and the |
| 853 | /// rest with `{}`, and hands back each request's body. |
| 854 | fn flaky_server(fail: usize, requests: usize) -> (String, std::thread::JoinHandle<Vec<Value>>) { |
| 855 | use std::io::{BufRead, BufReader, Read, Write}; |
| 856 | let listener = std::net::TcpListener::bind("127.0.0.1:0").unwrap(); |
| 857 | let base = format!("http://{}", listener.local_addr().unwrap()); |
| 858 | let serving = std::thread::spawn(move || { |
| 859 | let mut bodies = Vec::new(); |
| 860 | for answered in 0..requests { |
| 861 | let (stream, _) = listener.accept().unwrap(); |
| 862 | let mut reader = BufReader::new(stream); |
| 863 | let mut length = 0; |
| 864 | loop { |
| 865 | let mut header = String::new(); |
| 866 | reader.read_line(&mut header).unwrap(); |
| 867 | if header.trim().is_empty() { |
| 868 | break; |
| 869 | } |
| 870 | if let Some((name, value)) = header.split_once(':') |
| 871 | && name.eq_ignore_ascii_case("content-length") |
| 872 | { |
| 873 | length = value.trim().parse().unwrap(); |
| 874 | } |
| 875 | } |
| 876 | let mut body = vec![0; length]; |
| 877 | reader.read_exact(&mut body).unwrap(); |
| 878 | bodies.push(serde_json::from_slice::<Value>(&body).unwrap()); |
| 879 | let status = if answered < fail { "500 Internal Server Error" } else { "200 OK" }; |
| 880 | write!(reader.get_mut(), "HTTP/1.1 {status}\r\nContent-Length: 2\r\nConnection: close\r\n\r\n{{}}").unwrap(); |
| 881 | } |
| 882 | bodies |
| 883 | }); |
| 884 | (base, serving) |
| 885 | } |
| 886 | |
| 887 | #[test] |
| 888 | fn each_batch_of_the_log_keeps_its_number_when_sent_again() { |
| 889 | let (base, serving) = flaky_server(1, 3); |
| 890 | let mut log = Log::new(Api { base, job: "job_1".into(), token: "t".into() }, Vec::new()); |
| 891 | log.line("one"); |
| 892 | log.flush(); |
| 893 | // Sent before the next is handed over, or the two would go together. |
| 894 | log.settle(); |
| 895 | log.line("two"); |
| 896 | log.flush(); |
| 897 | log.flush(); // Nothing waits: no batch, and no number used. |
| 898 | let bodies = serving.join().unwrap(); |
| 899 | let sent: Vec<(u64, String)> = bodies |
| 900 | .iter() |
| 901 | .map(|body| (body["report"]["chunk"].as_u64().unwrap(), unstamped(body["report"]["text"].as_str().unwrap()))) |
| 902 | .collect(); |
| 903 | // The first batch failed and was sent again with its number; the |
| 904 | // next is the job's second. |
| 905 | assert_eq!(sent, [(1, "one\n".into()), (1, "one\n".into()), (2, "two\n".into())]); |
| 906 | assert_eq!(bodies[0], bodies[1], "a batch sent again is the same batch"); |
| 907 | } |
| 908 | |
| 909 | /// A g1t that answers each report `{}` after `slow(report)`, until the |
| 910 | /// job's `done`, and hands back each report as it came. |
| 911 | fn slow_server( |
| 912 | slow: impl Fn(&Value) -> Duration + Send + 'static, |
| 913 | ) -> (String, std::thread::JoinHandle<Vec<Value>>) { |
| 914 | use std::io::{BufRead, BufReader, Read, Write}; |
| 915 | let listener = std::net::TcpListener::bind("127.0.0.1:0").unwrap(); |
| 916 | let base = format!("http://{}", listener.local_addr().unwrap()); |
| 917 | let serving = std::thread::spawn(move || { |
| 918 | let mut reports = Vec::new(); |
| 919 | loop { |
| 920 | let (stream, _) = listener.accept().unwrap(); |
| 921 | let mut reader = BufReader::new(stream); |
| 922 | let mut length = 0; |
| 923 | loop { |
| 924 | let mut header = String::new(); |
| 925 | reader.read_line(&mut header).unwrap(); |
| 926 | if header.trim().is_empty() { |
| 927 | break; |
| 928 | } |
| 929 | if let Some((name, value)) = header.split_once(':') |
| 930 | && name.eq_ignore_ascii_case("content-length") |
| 931 | { |
| 932 | length = value.trim().parse().unwrap(); |
| 933 | } |
| 934 | } |
| 935 | let mut body = vec![0; length]; |
| 936 | reader.read_exact(&mut body).unwrap(); |
| 937 | let report = serde_json::from_slice::<Value>(&body).unwrap()["report"].clone(); |
| 938 | std::thread::sleep(slow(&report)); |
| 939 | write!( |
| 940 | reader.get_mut(), |
| 941 | "HTTP/1.1 200 OK\r\nContent-Length: 2\r\nConnection: close\r\n\r\n{{}}" |
| 942 | ) |
| 943 | .unwrap(); |
| 944 | let done = report["kind"] == "done"; |
| 945 | reports.push(report); |
| 946 | if done { |
| 947 | return reports; |
| 948 | } |
| 949 | } |
| 950 | }); |
| 951 | (base, serving) |
| 952 | } |
| 953 | |
| 954 | #[test] |
| 955 | fn a_slow_g1t_never_holds_a_step_and_its_log_catches_up_in_few_reports() { |
| 956 | // Each report takes 200 ms to answer, as g1t's took a second in |
| 957 | // Deploy #531, where a 300-line table went a line a second. |
| 958 | let (base, serving) = slow_server(|_| Duration::from_millis(200)); |
| 959 | let mut log = Log::new( |
| 960 | Api { |
| 961 | base, |
| 962 | job: "job_1".into(), |
| 963 | token: "t".into(), |
| 964 | }, |
| 965 | Vec::new(), |
| 966 | ); |
| 967 | log.steps(&["Build".into()]); |
| 968 | log.step(1); |
| 969 | log.step_state(1, "Build", "in_progress", None); |
| 970 | let started = Instant::now(); |
| 971 | for n in 0..300 { |
| 972 | log.line(&format!("line {n}")); |
| 973 | // The step's output comes over two seconds or so: lines still |
| 974 | // come while a batch is being sent. |
| 975 | if n % 30 == 0 { |
| 976 | log.flush(); |
| 977 | std::thread::sleep(Duration::from_millis(5)); |
| 978 | } |
| 979 | } |
| 980 | log.step_state(1, "Build", "completed", Some("success")); |
| 981 | assert!( |
| 982 | started.elapsed() < Duration::from_millis(200), |
| 983 | "the step waited on g1t: {:?}", |
| 984 | started.elapsed() |
| 985 | ); |
| 986 | log.done("success", &serde_json::Map::new(), None); |
| 987 | let reports = serving.join().unwrap(); |
| 988 | let logs: Vec<&Value> = reports |
| 989 | .iter() |
| 990 | .filter(|report| report["kind"] == "log") |
| 991 | .collect(); |
| 992 | // Far fewer reports than lines, numbered in order, with every line. |
| 993 | assert!(logs.len() < 30, "{} log reports for 300 lines", logs.len()); |
| 994 | let numbers: Vec<u64> = logs |
| 995 | .iter() |
| 996 | .map(|report| report["chunk"].as_u64().unwrap()) |
| 997 | .collect(); |
| 998 | assert_eq!(numbers, (1..=logs.len() as u64).collect::<Vec<_>>()); |
| 999 | let text: String = logs |
| 1000 | .iter() |
| 1001 | .map(|report| unstamped(report["text"].as_str().unwrap())) |
| 1002 | .collect(); |
| 1003 | let expected: String = (0..300).map(|n| format!("line {n}\n")).collect(); |
| 1004 | assert_eq!(text, expected); |
| 1005 | // The step's end went no later than the last of its log, and the |
| 1006 | // job's conclusion after all of it. |
| 1007 | let at = |find: &dyn Fn(&Value) -> bool| reports.iter().position(find).unwrap(); |
| 1008 | let completed = at(&|report| report["kind"] == "step" && report["status"] == "completed"); |
| 1009 | let last_log = reports |
| 1010 | .iter() |
| 1011 | .rposition(|report| report["kind"] == "log") |
| 1012 | .unwrap(); |
| 1013 | assert!(completed <= last_log + 1, "{reports:?}"); |
| 1014 | assert_eq!(reports.last().unwrap()["kind"], "done"); |
| 1015 | } |
| 1016 | |
| 1017 | #[test] |
| 1018 | fn a_log_that_cannot_keep_up_is_let_go_and_the_job_still_ends() { |
| 1019 | // Step 1's log takes a second and a half to be answered; the job's |
| 1020 | // end waits a tenth of a second for it, then lets step 2's go. |
| 1021 | let (arrived, sending) = mpsc::channel(); |
| 1022 | let (base, serving) = slow_server(move |report| { |
| 1023 | if report["kind"] == "log" { |
| 1024 | let _ = arrived.send(()); |
| 1025 | Duration::from_millis(1500) |
| 1026 | } else { |
| 1027 | Duration::ZERO |
| 1028 | } |
| 1029 | }); |
| 1030 | let mut log = Log::new( |
| 1031 | Api { |
| 1032 | base, |
| 1033 | job: "job_1".into(), |
| 1034 | token: "t".into(), |
| 1035 | }, |
| 1036 | Vec::new(), |
| 1037 | ); |
| 1038 | log.step(1); |
| 1039 | log.line("one"); |
| 1040 | log.flush(); |
| 1041 | sending.recv_timeout(Duration::from_secs(10)).unwrap(); |
| 1042 | log.step(2); |
| 1043 | log.line("two"); |
| 1044 | let started = Instant::now(); |
| 1045 | log.done_within( |
| 1046 | "success", |
| 1047 | &serde_json::Map::new(), |
| 1048 | None, |
| 1049 | Duration::from_millis(100), |
| 1050 | ); |
| 1051 | assert!( |
| 1052 | started.elapsed() < Duration::from_secs(10), |
| 1053 | "{:?}", |
| 1054 | started.elapsed() |
| 1055 | ); |
| 1056 | let reports = serving.join().unwrap(); |
| 1057 | let kinds: Vec<(&str, u64)> = reports |
| 1058 | .iter() |
| 1059 | .map(|report| { |
| 1060 | ( |
| 1061 | report["kind"].as_str().unwrap(), |
| 1062 | report["step"].as_u64().unwrap_or(0), |
| 1063 | ) |
| 1064 | }) |
| 1065 | .collect(); |
| 1066 | assert_eq!(kinds, [("log", 1), ("done", 0)]); |
| 1067 | } |
| 1068 | |
| 1069 | #[test] |
| 1070 | fn a_long_wait_says_so_in_the_log_as_it_goes() { |
| 1071 | let mut log = log(&[]); |
| 1072 | // The work answers once the log has told of the wait twice, so the |
| 1073 | // test does not hang on how fast the machine is; a minute at most. |
| 1074 | let told_so_far = std::sync::Arc::new(std::sync::atomic::AtomicUsize::new(0)); |
| 1075 | let seen = told_so_far.clone(); |
| 1076 | let started = Instant::now(); |
| 1077 | let answer = log.waiting( |
| 1078 | Duration::from_millis(50), |
| 1079 | move |_| { |
| 1080 | let deadline = Instant::now() + Duration::from_secs(60); |
| 1081 | while seen.load(std::sync::atomic::Ordering::SeqCst) < 2 && Instant::now() < deadline { |
| 1082 | std::thread::sleep(Duration::from_millis(5)); |
| 1083 | } |
| 1084 | 42 |
| 1085 | }, |
| 1086 | move |seconds| { |
| 1087 | told_so_far.fetch_add(1, std::sync::atomic::Ordering::SeqCst); |
| 1088 | format!("still waiting ({seconds}s)") |
| 1089 | }, |
| 1090 | ); |
| 1091 | let took = started.elapsed().as_millis() as usize; |
| 1092 | assert_eq!(answer, 42); |
| 1093 | let lines = log.buffered(); |
| 1094 | let told = lines.lines().filter(|line| line.starts_with("still waiting (")).count(); |
| 1095 | // At least the two it waited for, and never more than one per 50 ms |
| 1096 | // the wait really took. |
| 1097 | assert!(told >= 2 && told <= took / 50, "a line each time the wait goes on ({took} ms): {lines:?}"); |
| 1098 | // A wait that ends at once writes nothing. |
| 1099 | let mut quick = super::tests::log(&[]); |
| 1100 | assert_eq!(quick.waiting(Duration::from_secs(5), |api| api.job, |_| "never".into()), "job_1"); |
| 1101 | assert_eq!(quick.buffered(), ""); |
| 1102 | } |
| 1103 | |
| 1104 | #[test] |
| 1105 | fn outputs_holding_a_secret_are_left_out() { |
| 1106 | let mut log = log(&["s3cr3t-token"]); |
| 1107 | let mut outputs = serde_json::Map::new(); |
| 1108 | outputs.insert("version".into(), json!("1.2.0")); |
| 1109 | outputs.insert("leak".into(), json!("token=s3cr3t-token")); |
| 1110 | outputs.insert("encoded".into(), json!("czNjcjN0LXRva2Vu")); |
| 1111 | let kept = log.withhold_secrets(&outputs); |
| 1112 | assert_eq!(kept.keys().collect::<Vec<_>>(), ["version"]); |
| 1113 | assert!(log.buffer.contains("The output `leak` was left out")); |
| 1114 | assert!(log.buffer.contains("The output `encoded` was left out")); |
| 1115 | } |
| 1116 | |
| 1117 | #[test] |
| 1118 | fn a_cancelled_answer_is_heard_once_and_taken_in() { |
| 1119 | let cancel = Cancel::new(); |
| 1120 | cancel.hear(&json!({ "ok": true })); |
| 1121 | assert!(!cancel.cancelled()); |
| 1122 | cancel.hear(&json!({ "ok": true, "cancelled": true })); |
| 1123 | assert!(cancel.cancelled() && cancel.interrupt()); |
| 1124 | cancel.take(); |
| 1125 | assert!(cancel.cancelled() && !cancel.interrupt(), "cleanup steps are not stopped again"); |
| 1126 | cancel.hear(&json!({ "ok": true, "cancelled": false })); |
| 1127 | assert!(cancel.cancelled(), "a cancelled job stays cancelled"); |
| 1128 | } |
| 1129 | |
| 1130 | #[test] |
| 1131 | fn a_summary_past_its_limit_is_refused_in_the_log() { |
| 1132 | let mut log = log(&[]); |
| 1133 | log.summary(" |
| 1134 | "); |
| 1135 | assert!(log.buffer.is_empty(), "an empty summary is not sent"); |
| 1136 | log.summary(&"x".repeat(MAX_SUMMARY_BYTES + 1)); |
| 1137 | assert!(log.buffer.contains("$GITHUB_STEP_SUMMARY upload aborted")); |
| 1138 | assert!(log.buffer.contains("1025k")); |
| 1139 | } |
| 1140 | |
| 1141 | #[test] |
| 1142 | fn annotations_carry_their_columns_and_end() { |
| 1143 | let log = log(&["hidden"]); |
| 1144 | let properties: serde_json::Map<String, Value> = |
| 1145 | serde_json::from_value(json!({ "file": "a.rs", "line": "3", "col": "7", "endLine": "4", "endColumn": "2", "title": "t hidden" })).unwrap(); |
| 1146 | let report = log.annotation_report("error", "bad hidden", &properties); |
| 1147 | assert_eq!(report["line"], 3); |
| 1148 | assert_eq!(report["column"], 7); |
| 1149 | assert_eq!(report["end_line"], 4); |
| 1150 | assert_eq!(report["end_column"], 2); |
| 1151 | assert_eq!(report["title"], "t ***"); |
| 1152 | assert_eq!(report["message"], "bad ***"); |
| 1153 | let bare = log.annotation_report("notice", "x", &serde_json::Map::new()); |
| 1154 | assert!(bare["column"].is_null() && bare["file"].is_null()); |
| 1155 | } |
| 1156 | |
| 1157 | #[test] |
| 1158 | fn added_masks_cover_every_form() { |
| 1159 | let mut log = log(&[]); |
| 1160 | log.add_mask("line one\nline two"); |
| 1161 | assert_eq!(log.mask("first: line one"), "first: ***"); |
| 1162 | assert_eq!(log.mask("then line two"), "then ***"); |
| 1163 | // Longest first: the whole value, not its pieces. |
| 1164 | log.add_mask("abc"); |
| 1165 | log.add_mask("abcdef"); |
| 1166 | assert_eq!(log.mask("abcdef"), "***"); |
| 1167 | } |
| 1168 | } |