Set up job is no longer silent while g1t fetches an action. Before asking g1t where an action is, the job's log says `Download action repository 'owner/repo@ref'…`, and while g1t has not answered (the first job to use an action at a commit waits up to two minutes while g1t fetches its archive from GitHub) it says `Waiting for g1t to fetch 'owner/repo@ref' (10s)` every five seconds, sent as it is written; downloading the archive g1t keeps says `Downloading 'owner/repo@ref' from g1t (5s)` the same way. The request runs on a thread of its own with a copy of the job's API while the log waits on it (`Log::waiting`), which a test drives with a short wait. The Actions guide says so.
- Claude-Session:
- https://claude.ai/code/session_01PnwTRSNaC7vEHTAuBzjhrn
3 files+78−40/3 viewed
| 243 | 243 | GitHub, a tag before a branch of the same name, and looks again at | |
| 244 | 244 | most every 5 minutes, so a tag that moves is followed within minutes. | |
| 245 | 245 | 3. The first job to use an action at a commit has g1t fetch that commit's | |
| 246 | − | archive from GitHub and keep it. Every later job, in any workspace, | |
| 247 | − | downloads the same bytes from g1t. | |
| 246 | + | archive from GitHub and keep it, which can take up to two minutes. | |
| 247 | + | While it waits, **Set up job** says so every 5 seconds | |
| 248 | + | (`Waiting for g1t to fetch 'actions/setup-node@v4' (10s)`). Every | |
| 249 | + | later job, in any workspace, downloads the same bytes from g1t. | |
| 248 | 250 | ||
| 249 | 251 | While GitHub doesn't answer, a ref reads as the commit it last named, and | |
| 250 | 252 | the job says so in a warning; an action g1t keeps still downloads. An |
| 71 | 71 | CANCEL.take(); | |
| 72 | 72 | } | |
| 73 | 73 | ||
| 74 | + | #[derive(Clone)] | |
| 74 | 75 | pub(crate) struct Api { | |
| 75 | 76 | pub(crate) base: String, | |
| 76 | 77 | pub(crate) job: String, | |
| ⋯ | |||
| 278 | 279 | json!({ "kind": "log", "step": self.step, "chunk": self.chunk, "text": text }) | |
| 279 | 280 | } | |
| 280 | 281 | ||
| 282 | + | /// Does `work` with the job's API on a thread of its own, writing | |
| 283 | + | /// `waiting(seconds)` to the log, and sending it, every `every` it is | |
| 284 | + | /// still going: a wait the job's page would otherwise show as a silent | |
| 285 | + | /// log, such as g1t fetching an action's archive from GitHub. | |
| 286 | + | pub(crate) fn waiting<T: Send + 'static>( | |
| 287 | + | &mut self, | |
| 288 | + | every: Duration, | |
| 289 | + | work: impl FnOnce(Api) -> T + Send + 'static, | |
| 290 | + | waiting: impl Fn(u64) -> String, | |
| 291 | + | ) -> T { | |
| 292 | + | self.flush(); | |
| 293 | + | let api = self.api.clone(); | |
| 294 | + | let (done, answer) = std::sync::mpsc::channel(); | |
| 295 | + | let worker = std::thread::spawn(move || { | |
| 296 | + | let _ = done.send(work(api)); | |
| 297 | + | }); | |
| 298 | + | let started = Instant::now(); | |
| 299 | + | let result = loop { | |
| 300 | + | match answer.recv_timeout(every) { | |
| 301 | + | Ok(result) => break result, | |
| 302 | + | Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { | |
| 303 | + | self.line(&waiting(started.elapsed().as_secs())); | |
| 304 | + | self.flush(); | |
| 305 | + | } | |
| 306 | + | // The work panicked: so does the job, as it would have. | |
| 307 | + | Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => match worker.join() { | |
| 308 | + | Err(panic) => std::panic::resume_unwind(panic), | |
| 309 | + | Ok(()) => unreachable!("the work sends its result before it ends"), | |
| 310 | + | }, | |
| 311 | + | } | |
| 312 | + | }; | |
| 313 | + | let _ = worker.join(); | |
| 314 | + | result | |
| 315 | + | } | |
| 316 | + | ||
| 281 | 317 | pub(crate) fn steps(&self, names: &[String]) { | |
| 282 | 318 | self.api.report(json!({ "kind": "steps", "steps": names })); | |
| 283 | 319 | } | |
| ⋯ | |||
| 484 | 520 | } | |
| 485 | 521 | ||
| 486 | 522 | #[test] | |
| 523 | + | fn a_long_wait_says_so_in_the_log_as_it_goes() { | |
| 524 | + | let mut log = log(&[]); | |
| 525 | + | let answer = log.waiting(Duration::from_millis(50), |_| { | |
| 526 | + | std::thread::sleep(Duration::from_millis(180)); | |
| 527 | + | 42 | |
| 528 | + | }, |seconds| format!("still waiting ({seconds}s)")); | |
| 529 | + | assert_eq!(answer, 42); | |
| 530 | + | let lines = log.buffered(); | |
| 531 | + | let told = lines.lines().filter(|line| line.starts_with("still waiting (")).count(); | |
| 532 | + | assert!((2..=4).contains(&told), "a line each time the wait goes on: {lines:?}"); | |
| 533 | + | // A wait that ends at once writes nothing. | |
| 534 | + | let mut quick = super::tests::log(&[]); | |
| 535 | + | assert_eq!(quick.waiting(Duration::from_secs(5), |api| api.job, |_| "never".into()), "job_1"); | |
| 536 | + | assert_eq!(quick.buffered(), ""); | |
| 537 | + | } | |
| 538 | + | ||
| 539 | + | #[test] | |
| 487 | 540 | fn outputs_holding_a_secret_are_left_out() { | |
| 488 | 541 | let mut log = log(&["s3cr3t-token"]); | |
| 489 | 542 | let mut outputs = serde_json::Map::new(); | |
| 23 | 23 | use super::{Frame, Job, Post, PostRun}; | |
| 24 | 24 | ||
| 25 | 25 | const ACTIONS_DIR: &str = "/home/runner/_actions"; | |
| 26 | + | /// How often a wait on g1t for an action says it is still waiting, as | |
| 27 | + | /// transfers say how far they have got. | |
| 28 | + | const WAITING_EVERY: Duration = Duration::from_secs(5); | |
| 26 | 29 | ||
| 27 | 30 | /// Where an action comes from. | |
| 28 | 31 | enum Source { | |
| ⋯ | |||
| 226 | 229 | self.log.line(&format!("##[error]`{owner}/{repo}@{git_ref}` is not a name g1t can fetch.")); | |
| 227 | 230 | return None; | |
| 228 | 231 | } | |
| 229 | − | match self.log.api.action(&format!("{owner}/{repo}"), git_ref) { | |
| 232 | + | // The first job to use an action at a commit waits while g1t | |
| 233 | + | // fetches its archive from GitHub, up to two minutes: the log says | |
| 234 | + | // what it is waiting for, and that it still is, as GitHub's does. | |
| 235 | + | self.log.line(&format!("Download action repository '{owner}/{repo}@{git_ref}'…")); | |
| 236 | + | let repository = format!("{owner}/{repo}"); | |
| 237 | + | let asked = (repository.clone(), git_ref.to_owned()); | |
| 238 | + | let found = self.log.waiting( | |
| 239 | + | WAITING_EVERY, | |
| 240 | + | move |api| api.action(&asked.0, &asked.1), | |
| 241 | + | |seconds| format!("Waiting for g1t to fetch '{repository}@{git_ref}' ({seconds}s)"), | |
| 242 | + | ); | |
| 243 | + | match found { | |
| 230 | 244 | Ok(found) if found["source"] == "g1t" => self.fetch_g1t_action(&on_g1t, owner, repo, git_ref, &found), | |
| 231 | 245 | Ok(found) => { | |
| 232 | 246 | if let Some(note) = found["note"].as_str() { | |
| ⋯ | |||
| 290 | 304 | let dir = super::paths::under_home(ACTIONS_DIR).join(owner).join(repo).join(git_ref); | |
| 291 | 305 | self.log.line(&format!("Download action repository '{owner}/{repo}@{git_ref}' (SHA:{sha}) from g1t")); | |
| 292 | 306 | let archive = self.temp.join(format!("action{}.tar.gz", super::rand_id())); | |
| 293 | − | let downloaded = self.log.api.action_archive(&format!("{owner}/{repo}"), sha, &archive); | |
| 307 | + | let asked = (format!("{owner}/{repo}"), sha.to_owned(), archive.clone()); | |
| 308 | + | let downloaded = self.log.waiting( | |
| 309 | + | WAITING_EVERY, | |
| 310 | + | move |api| api.action_archive(&asked.0, &asked.1, &asked.2), | |
| 311 | + | |seconds| format!("Downloading '{owner}/{repo}@{git_ref}' from g1t ({seconds}s)"), | |
| 312 | + | ); | |
| 294 | 313 | let unpacked = match downloaded { | |
| 295 | 314 | Ok(_) => { | |
| 296 | 315 | let _ = std::fs::remove_dir_all(&dir); | |