/build/source/nativelink-worker/src/running_actions_manager.rs
Line | Count | Source |
1 | | // Copyright 2024 The NativeLink Authors. All rights reserved. |
2 | | // |
3 | | // Licensed under the Functional Source License, Version 1.1, Apache 2.0 Future License (the "License"); |
4 | | // you may not use this file except in compliance with the License. |
5 | | // You may obtain a copy of the License at |
6 | | // |
7 | | // See LICENSE file for details |
8 | | // |
9 | | // Unless required by applicable law or agreed to in writing, software |
10 | | // distributed under the License is distributed on an "AS IS" BASIS, |
11 | | // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
12 | | // See the License for the specific language governing permissions and |
13 | | // limitations under the License. |
14 | | |
15 | | use core::cmp::min; |
16 | | use core::convert::Into; |
17 | | use core::fmt::Debug; |
18 | | use core::pin::Pin; |
19 | | use core::sync::atomic::{AtomicBool, Ordering}; |
20 | | use core::time::Duration; |
21 | | use std::borrow::Cow; |
22 | | use std::collections::vec_deque::VecDeque; |
23 | | use std::collections::{HashMap, HashSet}; |
24 | | use std::env; |
25 | | use std::ffi::{OsStr, OsString}; |
26 | | #[cfg(target_family = "unix")] |
27 | | use std::fs::Permissions; |
28 | | #[cfg(target_family = "unix")] |
29 | | use std::os::unix::fs::{MetadataExt, PermissionsExt}; |
30 | | use std::path::{Path, PathBuf}; |
31 | | use std::process::Stdio; |
32 | | use std::sync::{Arc, Weak}; |
33 | | use std::time::SystemTime; |
34 | | |
35 | | use bytes::{Bytes, BytesMut}; |
36 | | use filetime::{FileTime, set_file_mtime}; |
37 | | use formatx::Template; |
38 | | use futures::future::{ |
39 | | BoxFuture, Future, FutureExt, TryFutureExt, join_all, try_join, try_join_all, |
40 | | }; |
41 | | use futures::stream::{FuturesUnordered, StreamExt, TryStreamExt}; |
42 | | use nativelink_config::cas_server::{ |
43 | | EnvironmentSource, UploadActionResultConfig, UploadCacheResultsStrategy, |
44 | | }; |
45 | | use nativelink_error::{Code, Error, ResultExt, make_err, make_input_err}; |
46 | | use nativelink_metric::MetricsComponent; |
47 | | use nativelink_proto::build::bazel::remote::execution::v2::{ |
48 | | Action, ActionResult as ProtoActionResult, Command as ProtoCommand, |
49 | | Directory as ProtoDirectory, Directory, DirectoryNode, ExecuteResponse, FileNode, SymlinkNode, |
50 | | Tree as ProtoTree, UpdateActionResultRequest, |
51 | | }; |
52 | | use nativelink_proto::com::github::trace_machina::nativelink::remote_execution::{ |
53 | | ActionResourceUsage, HistoricalExecuteResponse, StartExecute, |
54 | | }; |
55 | | use nativelink_store::ac_utils::{ |
56 | | ESTIMATED_DIGEST_SIZE, compute_buf_digest, get_and_decode_digest, serialize_and_upload_message, |
57 | | }; |
58 | | use nativelink_store::cas_utils::is_zero_digest; |
59 | | use nativelink_store::fast_slow_store::FastSlowStore; |
60 | | use nativelink_store::filesystem_store::{FileEntry, FileEntryImpl, FilesystemStore}; |
61 | | use nativelink_store::grpc_store::GrpcStore; |
62 | | use nativelink_util::action_messages::{ |
63 | | ActionInfo, ActionResult, DirectoryInfo, ExecutionMetadata, FileInfo, NameOrPath, OperationId, |
64 | | SymlinkInfo, to_execute_response, |
65 | | }; |
66 | | use nativelink_util::common::{DigestInfo, fs}; |
67 | | use nativelink_util::digest_hasher::{DigestHasher, DigestHasherFunc}; |
68 | | use nativelink_util::metrics_utils::{AsyncCounterWrapper, CounterWithTime}; |
69 | | use nativelink_util::store_trait::{Store, StoreLike, UploadSizeInfo}; |
70 | | use nativelink_util::{background_spawn, spawn, spawn_blocking}; |
71 | | use parking_lot::Mutex; |
72 | | use prost::Message; |
73 | | use relative_path::RelativePath; |
74 | | use scopeguard::{ScopeGuard, guard}; |
75 | | use serde::Deserialize; |
76 | | use tokio::io::{AsyncReadExt, AsyncSeekExt, AsyncWriteExt}; |
77 | | use tokio::process; |
78 | | use tokio::sync::{Notify, oneshot, watch}; |
79 | | use tokio::time::Instant; |
80 | | use tokio_stream::wrappers::ReadDirStream; |
81 | | use tonic::Request; |
82 | | use tracing::{debug, error, info, trace, warn}; |
83 | | use uuid::Uuid; |
84 | | |
85 | | use crate::persistent_worker::{ |
86 | | Input as PersistentWorkerInput, PersistentWorkerPool, WireFormat, WorkRequest, WorkerKey, |
87 | | }; |
88 | | |
89 | | /// For simplicity we use a fixed exit code for cases when our program is terminated |
90 | | /// due to a signal. |
91 | | const EXIT_CODE_FOR_SIGNAL: i32 = 9; |
92 | | |
93 | | const SUPPORTS_WORKERS_PROPERTY: &str = "supports-workers"; |
94 | | const REQUIRES_WORKER_PROTOCOL_PROPERTY: &str = "requires-worker-protocol"; |
95 | | |
96 | | /// Default strategy for uploading historical results. |
97 | | /// Note: If this value changes the config documentation |
98 | | /// should reflect it. |
99 | | const DEFAULT_HISTORICAL_RESULTS_STRATEGY: UploadCacheResultsStrategy = |
100 | | UploadCacheResultsStrategy::FailuresOnly; |
101 | | |
102 | | #[cfg(target_os = "linux")] |
103 | | const RESOURCE_USAGE_SAMPLE_INTERVAL: Duration = Duration::from_millis(250); |
104 | | |
105 | | /// What the sampler observed over an action's lifetime. |
106 | | #[cfg(target_os = "linux")] |
107 | | #[derive(Debug, Default, Clone, Copy, PartialEq, Eq)] |
108 | | struct SampledResourceUsage { |
109 | | peak_memory_kb: u64, |
110 | | cpu_time_ms: u64, |
111 | | } |
112 | | |
113 | | #[cfg(target_os = "linux")] |
114 | | struct ActionResourceUsageSampler { |
115 | | stop_tx: watch::Sender<bool>, |
116 | | handle: tokio::task::JoinHandle<SampledResourceUsage>, |
117 | | } |
118 | | |
119 | | #[cfg(target_os = "linux")] |
120 | 18 | fn start_action_resource_usage_sampler(pgid: u32) -> ActionResourceUsageSampler { |
121 | 18 | let (stop_tx, stop_rx) = watch::channel(false); |
122 | 18 | let handle = background_spawn!( |
123 | | "action_resource_usage_sampler", |
124 | 18 | sample_action_resource_usage(pgid, stop_rx) |
125 | | ); |
126 | 18 | ActionResourceUsageSampler { stop_tx, handle } |
127 | 18 | } |
128 | | |
129 | | #[cfg(target_os = "linux")] |
130 | 0 | async fn finish_action_resource_usage_sampler( |
131 | 0 | sampler: ActionResourceUsageSampler, |
132 | 18 | ) -> Option<SampledResourceUsage> { |
133 | 18 | let _ = sampler.stop_tx.send(true); |
134 | 18 | sampler.handle.await.ok() |
135 | 18 | } |
136 | | |
137 | | #[cfg(target_os = "linux")] |
138 | 18 | async fn sample_action_resource_usage( |
139 | 18 | pgid: u32, |
140 | 18 | mut stop_rx: watch::Receiver<bool>, |
141 | 18 | ) -> SampledResourceUsage { |
142 | 18 | let mut peak_memory_kb = 0; |
143 | | // CPU time is cumulative per process and a process that exits stops |
144 | | // appearing, so summing the live group at the end would lose everything |
145 | | // short-lived. Keep the last figure seen for each pid and total them at |
146 | | // the end instead. |
147 | 18 | let mut cpu_ticks_by_pid = HashMap::new(); |
148 | | |
149 | 36 | let sample18 = |peak_memory_kb: &mut u64, cpu_ticks_by_pid: &mut HashMap<u32, u64>| { |
150 | 36 | let observed = sample_process_group(pgid, cpu_ticks_by_pid); |
151 | 36 | if let Some(memory_kb16 ) = observed { |
152 | 16 | *peak_memory_kb = (*peak_memory_kb).max(memory_kb); |
153 | 20 | } |
154 | 36 | observed |
155 | 36 | }; |
156 | | |
157 | | loop { |
158 | 18 | if sample(&mut peak_memory_kb, &mut cpu_ticks_by_pid).is_none() |
159 | 2 | && !Path::new(&format!("/proc/{pgid}")).exists() |
160 | | { |
161 | | // The group leader has been reaped and no member process remains, |
162 | | // so the action is finished. |
163 | 0 | break; |
164 | 18 | } |
165 | | |
166 | 18 | if *stop_rx.borrow() { |
167 | 0 | break; |
168 | 18 | } |
169 | | |
170 | 18 | tokio::select! { |
171 | 18 | changed = stop_rx.changed() => { |
172 | 18 | if changed.is_ok() && *stop_rx.borrow() { |
173 | 18 | sample(&mut peak_memory_kb, &mut cpu_ticks_by_pid); |
174 | 18 | break; |
175 | 0 | } |
176 | | } |
177 | 18 | () = tokio::time::sleep(RESOURCE_USAGE_SAMPLE_INTERVAL) => {}0 |
178 | | } |
179 | | } |
180 | | |
181 | 18 | SampledResourceUsage { |
182 | 18 | peak_memory_kb, |
183 | 18 | cpu_time_ms: ticks_to_millis(cpu_ticks_by_pid.values().sum()), |
184 | 18 | } |
185 | 18 | } |
186 | | |
187 | | /// Converts clock ticks from `/proc` into milliseconds. |
188 | | /// |
189 | | /// `_SC_CLK_TCK` is 100 on every Linux we run on, but it is queryable so ask |
190 | | /// rather than assume, and fall back to 100 if the query fails. |
191 | | #[cfg(target_os = "linux")] |
192 | 18 | fn ticks_to_millis(ticks: u64) -> u64 { |
193 | | // SAFETY: `sysconf` takes an int and returns a long, with no memory |
194 | | // safety considerations. |
195 | 18 | let hz = unsafe { libc::sysconf(libc::_SC_CLK_TCK) }; |
196 | 18 | let hz = if hz > 0 { hz as u64 } else { 1000 }; |
197 | 18 | ticks.saturating_mul(1_000) / hz |
198 | 18 | } |
199 | | |
200 | | /// Sums the resident memory of every process in the action's process group. |
201 | | /// |
202 | | /// The action is spawned as its own process-group leader (see |
203 | | /// `command_builder.process_group(0)` in `inner_execute`), so `pgid` equals |
204 | | /// the spawned child's pid and every descendant inherits it. Sampling by |
205 | | /// process group — rather than walking the parent/child tree from the spawned |
206 | | /// pid — is required because an intermediate shell frequently exits and |
207 | | /// reparents the real workload to the worker (PID 1); the tree walk then sees |
208 | | /// only a childless zombie and reports zero. Process-group membership is |
209 | | /// inherited and survives reparenting, and excludes the worker's own group. |
210 | | /// Returns `None` when no member process can be read (the group is empty). |
211 | | #[cfg(target_os = "linux")] |
212 | 36 | fn sample_process_group(pgid: u32, cpu_ticks_by_pid: &mut HashMap<u32, u64>) -> Option<u64> { |
213 | 36 | let Ok(entries) = std::fs::read_dir("/proc") else { |
214 | 0 | return None; |
215 | | }; |
216 | | |
217 | 36 | let mut total_kb = 0; |
218 | 36 | let mut found_any_process = false; |
219 | 2.40k | for entry in entries36 .flatten36 () { |
220 | 2.40k | let Ok(member_pid177 ) = entry.file_name().to_string_lossy().parse::<u32>() else { |
221 | 2.23k | continue; |
222 | | }; |
223 | 177 | let Ok(stat) = std::fs::read_to_string(format!("/proc/{member_pid}/stat")) else { |
224 | 0 | continue; |
225 | | }; |
226 | 177 | if parse_pgid_from_stat(&stat) != Some(pgid) { |
227 | 144 | continue; |
228 | 33 | } |
229 | 33 | if let Some(ticks) = parse_cpu_ticks_from_stat(&stat) { |
230 | 33 | // Monotonic per process, but a pid could in principle be reused |
231 | 33 | // within one action, so never let the figure go backwards. |
232 | 33 | let entry = cpu_ticks_by_pid.entry(member_pid).or_insert(0); |
233 | 33 | *entry = (*entry).max(ticks); |
234 | 33 | }0 |
235 | 33 | if let Some(memory_kb28 ) = read_process_rss_kb(member_pid) { |
236 | 28 | total_kb += memory_kb; |
237 | 28 | found_any_process = true; |
238 | 28 | }5 |
239 | | } |
240 | | |
241 | 36 | found_any_process.then_some(total_kb) |
242 | 36 | } |
243 | | |
244 | | #[cfg(target_os = "linux")] |
245 | 33 | fn read_process_rss_kb(pid: u32) -> Option<u64> { |
246 | 33 | let status = std::fs::read_to_string(format!("/proc/{pid}/status")).ok()?0 ; |
247 | 853 | status.lines()33 .find_map33 (|line| { |
248 | 853 | let rest28 = line.strip_prefix("VmRSS:")?825 ; |
249 | 28 | rest.split_whitespace().next()?0 .parse().ok() |
250 | 853 | }) |
251 | 33 | } |
252 | | |
253 | | /// Parses the process group id (`pgrp`, field 5) from the contents of a |
254 | | /// `/proc/<pid>/stat` line. |
255 | | /// |
256 | | /// `comm` (field 2) can contain spaces and parentheses, so fields are parsed |
257 | | /// relative to the final `)` to avoid miscounting. Returns `None` when the |
258 | | /// line is malformed. |
259 | | #[cfg(target_os = "linux")] |
260 | 182 | pub fn parse_pgid_from_stat(stat: &str) -> Option<u32> { |
261 | 182 | let after_comm180 = stat.rsplit_once(')')?2 .1; |
262 | | // Fields after the final ')': state(0) ppid(1) pgrp(2) ... |
263 | 180 | after_comm.split_whitespace().nth(2)?1 .parse179 ().ok179 () |
264 | 182 | } |
265 | | |
266 | | /// Sums user and system CPU ticks (`utime` + `stime`, fields 14 and 15) from |
267 | | /// the contents of a `/proc/<pid>/stat` line. |
268 | | /// |
269 | | /// Parsed relative to the final `)` for the same reason as the pgid above: |
270 | | /// `comm` can contain spaces and parentheses. Returns `None` when the line is |
271 | | /// malformed. |
272 | | /// |
273 | | /// `cutime`/`cstime` are deliberately not included. They only cover children |
274 | | /// this process has already reaped, so adding them here would double count |
275 | | /// every child that is still its own entry in the group. |
276 | | #[cfg(target_os = "linux")] |
277 | 38 | pub fn parse_cpu_ticks_from_stat(stat: &str) -> Option<u64> { |
278 | 38 | let after_comm36 = stat.rsplit_once(')')?2 .1; |
279 | 36 | let mut fields = after_comm.split_whitespace(); |
280 | | // Fields after the final ')': state(0) ppid(1) pgrp(2) session(3) tty(4) |
281 | | // tpgid(5) flags(6) minflt(7) cminflt(8) majflt(9) cmajflt(10) |
282 | | // utime(11) stime(12) ... |
283 | 36 | let utime35 : u6435 = fields.nth(11)?1 .parse35 ().ok35 ()?0 ; |
284 | 35 | let stime: u64 = fields.next()?0 .parse().ok()?0 ; |
285 | 35 | Some(utime.saturating_add(stime)) |
286 | 38 | } |
287 | | |
288 | | /// Valid string reasons for a failure. |
289 | | /// Note: If these change, the documentation should be updated. |
290 | | #[derive(Debug, Deserialize)] |
291 | | #[serde(rename_all = "snake_case")] |
292 | | enum SideChannelFailureReason { |
293 | | /// Task should be considered timed out. |
294 | | Timeout, |
295 | | } |
296 | | |
297 | | /// This represents the json data that can be passed from the running process |
298 | | /// to the parent via the `SideChannelFile`. See: |
299 | | /// `config::EnvironmentSource::sidechannelfile` for more details. |
300 | | /// Note: Any fields added here must be added to the documentation. |
301 | | #[derive(Debug, Deserialize, Default)] |
302 | | struct SideChannelInfo { |
303 | | /// If the task should be considered a failure and why. |
304 | | failure: Option<SideChannelFailureReason>, |
305 | | } |
306 | | |
307 | 20 | fn action_supports_persistent_workers( |
308 | 20 | action_info: &ActionInfo, |
309 | 20 | ) -> Option<Result<WireFormat, Error>> { |
310 | 20 | if action_info |
311 | 20 | .platform_properties |
312 | 20 | .get(SUPPORTS_WORKERS_PROPERTY) |
313 | 20 | .is_none_or(|value| value2 != "1"2 ) |
314 | | { |
315 | 18 | return None; |
316 | 2 | } |
317 | | |
318 | 2 | let protocol = action_info |
319 | 2 | .platform_properties |
320 | 2 | .get(REQUIRES_WORKER_PROTOCOL_PROPERTY) |
321 | 2 | .map_or("proto", String::as_str); |
322 | 2 | Some(WireFormat::parse(protocol)) |
323 | 20 | } |
324 | | |
325 | 2 | fn os_args_to_strings(args: &[&OsStr]) -> Result<Vec<String>, Error> { |
326 | 2 | args.iter() |
327 | 4 | .map2 (|arg| { |
328 | 4 | arg.to_str().map(str::to_owned).ok_or_else(|| {0 |
329 | 0 | make_err!( |
330 | 0 | Code::InvalidArgument, |
331 | | "Persistent worker command arguments must be valid UTF-8: {arg:?}" |
332 | | ) |
333 | 0 | }) |
334 | 4 | }) |
335 | 2 | .collect() |
336 | 2 | } |
337 | | |
338 | 2 | fn persistent_worker_request_arguments(argv: &[String]) -> Vec<String> { |
339 | 2 | argv.iter() |
340 | 2 | .skip(1) |
341 | 2 | .skip_while(|arg| !arg.starts_with('@')) |
342 | 2 | .cloned() |
343 | 2 | .collect() |
344 | 2 | } |
345 | | /// Maximum number of file-materialization (hardlink) or subdirectory |
346 | | /// recursion futures polled concurrently per directory level. Higher values |
347 | | /// drown APFS's per-volume metadata lock with `hardlink(2)` syscalls and |
348 | | /// regress overall throughput vs lower-contention concurrency. |
349 | | /// |
350 | | /// 64 is well above the inflection point on any modern Linux filesystem, |
351 | | /// so this is also a no-op on Linux beyond replacing tokio scheduling |
352 | | /// overhead. |
353 | | const DOWNLOAD_TO_DIRECTORY_CONCURRENCY: usize = 64; |
354 | | |
355 | | /// Keeps every digest used by an action present in locally eviction-managed |
356 | | /// CAS tiers. |
357 | | /// |
358 | | /// A lease is registered before a digest is populated. This is important for |
359 | | /// blobs that are not yet in the fast tier: reserving the key first prevents |
360 | | /// the insertion that follows from immediately evicting the blob under pressure. |
361 | | /// Every directly discoverable filesystem tier of the worker's |
362 | | /// `FastSlowStore` is leased when present (including a `RefStore` target). |
363 | | /// Transforming wrappers remain opaque by design. The reference count lets |
364 | | /// concurrent actions share a digest safely. |
365 | | #[derive(Debug)] |
366 | | struct ActionInputLease { |
367 | | filesystem_stores: Vec<Arc<FilesystemStore>>, |
368 | | digests: Mutex<Option<HashSet<DigestInfo>>>, |
369 | | } |
370 | | |
371 | | impl ActionInputLease { |
372 | 1 | fn new( |
373 | 1 | cas_store: &FastSlowStore, |
374 | 1 | command_digest: DigestInfo, |
375 | 1 | input_root_digest: DigestInfo, |
376 | 1 | ) -> Arc<Self> { |
377 | 1 | let lease = Arc::new(Self { |
378 | 1 | filesystem_stores: cas_store.get_filesystem_stores(), |
379 | 1 | digests: Mutex::new(Some(HashSet::new())), |
380 | 1 | }); |
381 | 1 | lease.lease_digest(&command_digest); |
382 | 1 | lease.lease_digest(&input_root_digest); |
383 | 1 | lease |
384 | 1 | } |
385 | | |
386 | 4 | fn lease_digest(&self, digest: &DigestInfo) { |
387 | 4 | let mut digests = self.digests.lock(); |
388 | 4 | let Some(digests) = digests.as_mut() else { |
389 | 0 | return; |
390 | | }; |
391 | 4 | if digests.insert(*digest) { |
392 | 3 | for filesystem_store in &self.filesystem_stores { |
393 | 3 | filesystem_store.lease_digest(digest); |
394 | 3 | } |
395 | 1 | } |
396 | 4 | } |
397 | | |
398 | 2 | fn take_release_work(&self) -> Option<(Vec<Arc<FilesystemStore>>, Vec<DigestInfo>)> { |
399 | 2 | let digests1 = self.digests.lock().take()?1 .into_iter1 ().collect1 (); |
400 | 1 | Some((self.filesystem_stores.clone(), digests)) |
401 | 2 | } |
402 | | |
403 | 2 | fn spawn_release(&self) -> Option<tokio::task::JoinHandle<()>> { |
404 | 2 | let (filesystem_stores1 , digests1 ) = self.take_release_work()?1 ; |
405 | 1 | Some(background_spawn!( |
406 | | "action_input_lease_release", |
407 | 1 | release_filesystem_stores(filesystem_stores, digests) |
408 | | )) |
409 | 2 | } |
410 | | |
411 | 2 | async fn release(self: Arc<Self>) {1 |
412 | 1 | let Some(handle) = self.spawn_release() else { |
413 | 0 | return; |
414 | | }; |
415 | | // Detach the actual release before awaiting it so cancellation of the |
416 | | // action cleanup future cannot strand leases in a later filesystem |
417 | | // tier. |
418 | 1 | let _result = handle.await; |
419 | 1 | } |
420 | | } |
421 | | |
422 | | impl crate::directory_cache::DigestLease for ActionInputLease { |
423 | 2 | fn acquire(&self, digest: &DigestInfo) { |
424 | 2 | self.lease_digest(digest); |
425 | 2 | } |
426 | | } |
427 | | |
428 | | impl Drop for ActionInputLease { |
429 | 1 | fn drop(&mut self) { |
430 | 1 | drop(self.spawn_release()); |
431 | 1 | } |
432 | | } |
433 | | |
434 | 1 | async fn release_filesystem_stores( |
435 | 1 | filesystem_stores: Vec<Arc<FilesystemStore>>, |
436 | 1 | digests: Vec<DigestInfo>, |
437 | 1 | ) { |
438 | 1 | join_all( |
439 | 1 | filesystem_stores |
440 | 1 | .iter() |
441 | 1 | .map(|filesystem_store| filesystem_store.release_digests(&digests)), |
442 | | ) |
443 | 1 | .await; |
444 | 1 | } |
445 | | |
446 | | /// Aggressively download the digests of files and make a local folder from it. This function |
447 | | /// gates each directory level to at most `DOWNLOAD_TO_DIRECTORY_CONCURRENCY` |
448 | | /// concurrent in-flight materialization futures. |
449 | | /// We require the `FilesystemStore` to be the `fast` store of `FastSlowStore`. This is for |
450 | | /// efficiency reasons. We will request the `FastSlowStore` to populate the entry then we will |
451 | | /// assume the `FilesystemStore` has the file available immediately after and hardlink the file |
452 | | /// to a new location. |
453 | | // Sadly we cannot use `async fn` here because the rust compiler cannot determine the auto traits |
454 | | // of the future. So we need to force this function to return a dynamic future instead. |
455 | | // see: https://github.com/rust-lang/rust/issues/78649 |
456 | 5 | pub fn download_to_directory<'a>( |
457 | 5 | cas_store: &'a FastSlowStore, |
458 | 5 | filesystem_store: Pin<&'a FilesystemStore>, |
459 | 5 | digest: &'a DigestInfo, |
460 | 5 | current_directory: &'a str, |
461 | 5 | ) -> BoxFuture<'a, Result<(), Error>> { |
462 | 5 | download_to_directory_with_lease(cas_store, filesystem_store, digest, current_directory, None) |
463 | 5 | } |
464 | | |
465 | 28 | fn download_to_directory_with_lease<'a>( |
466 | 28 | cas_store: &'a FastSlowStore, |
467 | 28 | filesystem_store: Pin<&'a FilesystemStore>, |
468 | 28 | digest: &'a DigestInfo, |
469 | 28 | current_directory: &'a str, |
470 | 28 | input_lease: Option<Arc<ActionInputLease>>, |
471 | 28 | ) -> BoxFuture<'a, Result<(), Error>> { |
472 | 28 | async move { |
473 | 28 | let (dirs, files, inline_nodes) = |
474 | 28 | collect_download_links(cas_store, digest, current_directory, input_lease).await?0 ; |
475 | | |
476 | 28 | let (exec_files, plain_files): (Vec<_>, Vec<_>) = |
477 | 28 | files.into_iter().partition(|file| file.executable); |
478 | 28 | let mut links = resolve_plain_files(cas_store, filesystem_store, plain_files).await?0 ; |
479 | 28 | links.extend(resolve_exec_files(cas_store, filesystem_store, exec_files).await?0 ); |
480 | | |
481 | | // Every directory exists before anything is written into one, so no |
482 | | // later pass has to create a parent it happens to need. |
483 | 28 | fs::create_dir_many(dirs).await?0 ; |
484 | 28 | materialize_inline_nodes(cas_store, filesystem_store, inline_nodes).await?0 ; |
485 | 28 | materialize_links(filesystem_store, links).await |
486 | 28 | } |
487 | 28 | .boxed() |
488 | 28 | } |
489 | | |
490 | | /// A hardlink deferred to the end of the input-tree walk, so the whole tree is |
491 | | /// materialized by one batched [`fs::hard_link_many`] pass instead of one |
492 | | /// `spawn_blocking` dispatch per file. |
493 | | struct PendingLink { |
494 | | src: PathBuf, |
495 | | dst: PathBuf, |
496 | | /// Keeps the CAS blob's `FileEntry` alive until the link is made, so the |
497 | | /// inode cannot be dropped out from under the batch. `None` for an |
498 | | /// executable variant, which is a private file outside the entry map and so |
499 | | /// has no entry to hold. |
500 | | /// |
501 | | /// Neither case is fully closed: a held entry pins the inode but does not |
502 | | /// stop an eviction from *renaming* the blob, and a variant is deleted |
503 | | /// outright by the eviction callback. Both races predate batching, which |
504 | | /// widens the window from a single file to a whole input tree. An operator |
505 | | /// seeing `NotFound` during staging should enable |
506 | | /// `experimental_active_input_leases`, since a leased digest is not |
507 | | /// evicted, or raise the store's `max_bytes`. The durable fix is a |
508 | | /// `hard_link_locked_many` holding every read guard across the batch. |
509 | | _keepalive: Option<Arc<FileEntryImpl>>, |
510 | | } |
511 | | |
512 | | /// A file whose CAS blob has not been resolved to a path yet. |
513 | | struct PendingFile { |
514 | | digest: DigestInfo, |
515 | | dst: String, |
516 | | executable: bool, |
517 | | } |
518 | | |
519 | | /// The directories to create, the files to hardlink, and the nodes to |
520 | | /// materialize one at a time, for one input subtree. |
521 | | type CollectedTree = (Vec<PathBuf>, Vec<PendingFile>, Vec<InlineNode>); |
522 | | |
523 | | /// Executes every deferred hardlink of an input tree in one batched pass. |
524 | 28 | async fn materialize_links( |
525 | 28 | filesystem_store: Pin<&FilesystemStore>, |
526 | 28 | links: Vec<PendingLink>, |
527 | 28 | ) -> Result<(), Error> { |
528 | 28 | let pairs = links |
529 | 28 | .iter() |
530 | 28 | .map(|link| (link.src12 .clone12 (), link.dst12 .clone12 ())) |
531 | 28 | .collect(); |
532 | 28 | for (link12 , result12 ) in links.iter().zip(fs::hard_link_many(pairs).await?0 ) { |
533 | 12 | let (src_path, dest) = (&link.src, &link.dst); |
534 | 12 | result.map_err(|e| {0 |
535 | 0 | let src_metadata = std::fs::metadata(src_path); |
536 | 0 | let dest_metadata = std::fs::metadata(dest); |
537 | 0 | let dest_parent_metadata = dest.parent().map(Path::metadata); |
538 | 0 | let snapshot = filesystem_store.get_eviction_snapshot(); |
539 | 0 | warn!(?e, fs_eviction_snapshot = %snapshot, ?src_path, ?src_metadata, ?dest, ?dest_metadata, ?dest_parent_metadata, "Could not make hardlink"); |
540 | 0 | if e.code == Code::NotFound { |
541 | 0 | e.append( |
542 | 0 | format!( |
543 | | "Could not make hardlink from {} to {}, file was likely evicted from cache.\n\ |
544 | | This error often occurs when the filesystem store's max_bytes is too small for your workload.\n\ |
545 | | To fix this issue:\n\ |
546 | | 1. Increase the 'max_bytes' value in your filesystem store configuration\n\ |
547 | | 2. Example: Change 'max_bytes: 10000000000' to 'max_bytes: 50000000000' (or higher)\n\ |
548 | | 3. The setting is typically found in your nativelink.json config under:\n\ |
549 | | stores -> [your_filesystem_store] -> filesystem -> eviction_policy -> max_bytes\n\ |
550 | | 4. Restart NativeLink after making the change\n\n\ |
551 | | If this error persists after increasing max_bytes several times, please report at:\n\ |
552 | | https://github.com/TraceMachina/nativelink/issues\n\ |
553 | | Include your config file and both server and client logs to help us assist you.", |
554 | 0 | src_path.display(), dest.display() |
555 | | )) |
556 | | } else { |
557 | 0 | e.append(format!("Could not make hardlink from {} to {}", src_path.display(), dest.display())) |
558 | | } |
559 | 0 | })?; |
560 | | } |
561 | 28 | Ok(()) |
562 | 28 | } |
563 | | |
564 | | /// Resolves every non-executable file of an input tree to its CAS blob path. |
565 | | /// |
566 | | /// The blob is nearly always resident, and `populate_fast_store` would take the |
567 | | /// store's eviction lock only to discover that, so resolving the entry directly |
568 | | /// answers the same question and yields the path. Only a genuine miss pays the |
569 | | /// populate round trip. |
570 | 28 | async fn resolve_plain_files( |
571 | 28 | cas_store: &FastSlowStore, |
572 | 28 | filesystem_store: Pin<&FilesystemStore>, |
573 | 28 | files: Vec<PendingFile>, |
574 | 28 | ) -> Result<Vec<PendingLink>, Error> { |
575 | 28 | let mut tasks = Vec::with_capacity(files.len()); |
576 | 28 | for file9 in files { |
577 | 9 | tasks.push(async move { |
578 | 9 | let file_entry = if let Ok(entry2 ) = filesystem_store |
579 | 9 | .get_file_entry_for_digest(&file.digest) |
580 | 9 | .await |
581 | | { |
582 | 2 | entry |
583 | | } else { |
584 | 7 | cas_store |
585 | 7 | .populate_fast_store(file.digest.into()) |
586 | 7 | .await |
587 | 7 | .err_tip(|| "Populating fast store for hard link")?0 ; |
588 | 7 | filesystem_store |
589 | 7 | .get_file_entry_for_digest(&file.digest) |
590 | 7 | .await |
591 | 7 | .err_tip(|| "During hard link")?0 |
592 | | }; |
593 | | // TODO: add a test for #2051: deadlock with large number of files |
594 | 9 | let src_path = file_entry |
595 | 18 | .get_file_path_locked9 (|src| async move {9 Ok(src)9 }) |
596 | 9 | .await |
597 | 9 | .err_tip(|| format!0 ("for digest {}", file.digest))?0 ; |
598 | 9 | Ok::<_, Error>(PendingLink { |
599 | 9 | src: PathBuf::from(src_path), |
600 | 9 | dst: PathBuf::from(file.dst), |
601 | 9 | _keepalive: Some(file_entry), |
602 | 9 | }) |
603 | 9 | }); |
604 | | } |
605 | 28 | collect_links(tasks).await |
606 | 28 | } |
607 | | |
608 | | /// Runs the resolution tasks of one input tree, bounded, into the link batch. |
609 | 56 | async fn collect_links( |
610 | 56 | tasks: Vec<impl Future<Output = Result<PendingLink, Error>>>, |
611 | 56 | ) -> Result<Vec<PendingLink>, Error> { |
612 | 56 | futures::stream::iter(tasks) |
613 | 56 | .buffer_unordered(DOWNLOAD_TO_DIRECTORY_CONCURRENCY) |
614 | 56 | .try_collect() |
615 | 56 | .await |
616 | 56 | } |
617 | | |
618 | | /// Resolves every executable file of an input tree to its 0o555 variant. |
619 | | /// |
620 | | /// The shared 0o444 CAS blob cannot carry the executable bit, so each of these |
621 | | /// digests hardlinks a private variant instead, and the batch checks the whole |
622 | | /// tree's variants for existence in one dispatch. |
623 | | /// |
624 | | /// A variant cannot be built from a blob that is not resident, and only this |
625 | | /// caller can fetch one, so those digests are populated and retried here. |
626 | 28 | async fn resolve_exec_files( |
627 | 28 | cas_store: &FastSlowStore, |
628 | 28 | filesystem_store: Pin<&FilesystemStore>, |
629 | 28 | files: Vec<PendingFile>, |
630 | 28 | ) -> Result<Vec<PendingLink>, Error> { |
631 | 28 | let digests: Vec<DigestInfo> = files.iter().map(|file| file.digest).collect(); |
632 | 28 | let sources = filesystem_store |
633 | 28 | .get_executable_hardlink_sources(&digests) |
634 | 28 | .await; |
635 | | |
636 | 28 | let mut tasks = Vec::with_capacity(files.len()); |
637 | 28 | for (file3 , source3 ) in files.into_iter().zip(sources) { |
638 | 3 | tasks.push(async move { |
639 | 3 | let src_path = if let Ok(src_path2 ) = source { |
640 | 2 | src_path |
641 | | } else { |
642 | 1 | cas_store |
643 | 1 | .populate_fast_store(file.digest.into()) |
644 | 1 | .await |
645 | 1 | .err_tip(|| "Populating fast store for executable")?0 ; |
646 | 1 | filesystem_store |
647 | 1 | .get_executable_hardlink_source(&file.digest) |
648 | 1 | .await |
649 | 1 | .err_tip(|| format!0 ("Resolving executable variant for {}", file.digest))?0 |
650 | | }; |
651 | 3 | Ok::<_, Error>(PendingLink { |
652 | 3 | src: PathBuf::from(src_path), |
653 | 3 | dst: PathBuf::from(file.dst), |
654 | 3 | _keepalive: None, |
655 | 3 | }) |
656 | 3 | }); |
657 | | } |
658 | 28 | collect_links(tasks).await |
659 | 28 | } |
660 | | |
661 | | /// Walks the input tree, reading its `Directory` protos and sorting every node |
662 | | /// into one of the passes the caller then runs: directories to create, files to |
663 | | /// hardlink in a batch, and the few nodes that need individual treatment. |
664 | | /// |
665 | | /// Nothing is written to disk here, which is what lets the caller create every |
666 | | /// directory before any node is materialized into one. |
667 | 40 | fn collect_download_links<'a>( |
668 | 40 | cas_store: &'a FastSlowStore, |
669 | 40 | digest: &'a DigestInfo, |
670 | 40 | current_directory: &'a str, |
671 | 40 | input_lease: Option<Arc<ActionInputLease>>, |
672 | 40 | ) -> BoxFuture<'a, Result<CollectedTree, Error>> { |
673 | 40 | async move { |
674 | 40 | if let Some(input_lease0 ) = &input_lease { |
675 | 0 | input_lease.lease_digest(digest); |
676 | 40 | } |
677 | 40 | let directory = get_and_decode_digest::<ProtoDirectory>(cas_store, digest.into()) |
678 | 40 | .await |
679 | 40 | .err_tip(|| "Converting digest to Directory")?0 ; |
680 | 40 | let mut futures = Vec::new(); |
681 | 40 | let mut pending_files = Vec::new(); |
682 | 40 | let mut inline_nodes = Vec::new(); |
683 | | |
684 | 40 | for file18 in directory.files { |
685 | 18 | let digest: DigestInfo = file |
686 | 18 | .digest |
687 | 18 | .err_tip(|| "Expected Digest to exist in Directory::file::digest")?0 |
688 | 18 | .try_into() |
689 | 18 | .err_tip(|| "In Directory::file::digest")?0 ; |
690 | 18 | let dest = format!("{}/{}", current_directory, file.name); |
691 | 18 | let is_executable = file.is_executable; |
692 | 18 | let (mtime, custom_unix_mode) = match file.node_properties { |
693 | 2 | Some(properties) => (properties.mtime, properties.unix_mode), |
694 | 16 | None => (None, None), |
695 | | }; |
696 | 18 | if let Some(input_lease0 ) = &input_lease { |
697 | 0 | input_lease.lease_digest(&digest); |
698 | 18 | } |
699 | | // Hot path: nothing to stamp, so the file needs nothing from the |
700 | | // walk beyond its digest. Hand it up unresolved and let the caller |
701 | | // resolve and link the whole tree in one batch. |
702 | 18 | if mtime.is_none() && custom_unix_mode16 .is_none16 () && !is_zero_digest(digest)16 { |
703 | 12 | pending_files.push(PendingFile { |
704 | 12 | digest, |
705 | 12 | dst: dest, |
706 | 12 | executable: is_executable, |
707 | 12 | }); |
708 | 12 | continue; |
709 | 6 | } |
710 | 6 | inline_nodes.push(InlineNode::File { |
711 | 6 | digest, |
712 | 6 | dst: dest, |
713 | 6 | is_executable, |
714 | 6 | mtime: mtime |
715 | 6 | .map(|mtime| FileTime::from_unix_time2 (mtime.seconds2 , mtime.nanos as u322 )), |
716 | 6 | custom_unix_mode, |
717 | | }); |
718 | | } |
719 | | |
720 | 40 | for sub_directory12 in directory.directories { |
721 | 12 | let digest: DigestInfo = sub_directory |
722 | 12 | .digest |
723 | 12 | .err_tip(|| "Expected Digest to exist in Directory::directories::digest")?0 |
724 | 12 | .try_into() |
725 | 12 | .err_tip(|| "In Directory::file::digest")?0 ; |
726 | 12 | let new_directory_path = format!("{}/{}", current_directory, sub_directory.name); |
727 | 12 | if let Some(input_lease0 ) = &input_lease { |
728 | 0 | // Reserve queued child directories before their futures are |
729 | 0 | // polled. Without this, a large parent can leave later |
730 | 0 | // directory digests exposed to slow-tier eviction while the |
731 | 0 | // first batch of children is being materialized. |
732 | 0 | input_lease.lease_digest(&digest); |
733 | 12 | } |
734 | 12 | let input_lease = input_lease.clone(); |
735 | 12 | futures.push( |
736 | 12 | async move { |
737 | 12 | let (mut sub_dirs, files, inline) = collect_download_links( |
738 | 12 | cas_store, |
739 | 12 | &digest, |
740 | 12 | &new_directory_path, |
741 | 12 | input_lease, |
742 | 12 | ) |
743 | 12 | .await |
744 | 12 | .err_tip(|| format!0 ("in download_to_directory : {new_directory_path}"))?0 ; |
745 | 12 | sub_dirs.push(PathBuf::from(new_directory_path)); |
746 | 12 | Ok::<_, Error>((sub_dirs, files, inline)) |
747 | 12 | } |
748 | 12 | .boxed(), |
749 | | ); |
750 | | } |
751 | | |
752 | | #[cfg(target_family = "unix")] |
753 | 40 | for symlink_node3 in directory.symlinks { |
754 | 3 | inline_nodes.push(InlineNode::Symlink { |
755 | 3 | target: symlink_node.target, |
756 | 3 | dst: format!("{}/{}", current_directory, symlink_node.name), |
757 | 3 | }); |
758 | 3 | } |
759 | | |
760 | | // Gate concurrency: at most DOWNLOAD_TO_DIRECTORY_CONCURRENCY futures |
761 | | // polled at once for this directory level. Previously all futures were |
762 | | // pushed into an unbounded FuturesUnordered, which on macOS produced |
763 | | // thousands of parallel hardlink(2) calls fighting APFS's per-volume |
764 | | // metadata lock and regressing throughput vs serial. |
765 | 40 | let collected: Vec<CollectedTree> = futures::stream::iter(futures) |
766 | 40 | .buffer_unordered(DOWNLOAD_TO_DIRECTORY_CONCURRENCY) |
767 | 40 | .try_collect() |
768 | 40 | .await?0 ; |
769 | | |
770 | 40 | let mut dirs = Vec::new(); |
771 | 40 | for (sub_dirs12 , sub_files12 , sub_inline12 ) in collected { |
772 | 12 | dirs.extend(sub_dirs); |
773 | 12 | pending_files.extend(sub_files); |
774 | 12 | inline_nodes.extend(sub_inline); |
775 | 12 | } |
776 | 40 | Ok((dirs, pending_files, inline_nodes)) |
777 | 40 | } |
778 | 40 | .boxed() |
779 | 40 | } |
780 | | |
781 | | /// A node materialized one at a time rather than through a batch, because it |
782 | | /// needs a private inode or is not a hardlink at all. |
783 | | /// |
784 | | /// These are a tiny fraction of an input tree, and deferring them alongside the |
785 | | /// batched files keeps one ordering rule for the whole walk: nothing is written |
786 | | /// until every directory exists. |
787 | | enum InlineNode { |
788 | | /// A zero-digest file, or one carrying metadata that must be stamped onto |
789 | | /// an inode private to this action. |
790 | | File { |
791 | | digest: DigestInfo, |
792 | | dst: String, |
793 | | is_executable: bool, |
794 | | mtime: Option<FileTime>, |
795 | | custom_unix_mode: Option<u32>, |
796 | | }, |
797 | | #[cfg(target_family = "unix")] |
798 | | Symlink { target: String, dst: String }, |
799 | | } |
800 | | |
801 | | /// Stamps the mode an input file asked for. `dest` must be an inode private to |
802 | | /// this action: the same call on a hardlinked CAS blob would mutate the inode |
803 | | /// every other action shares. |
804 | | #[cfg(target_family = "unix")] |
805 | 6 | async fn stamp_unix_mode( |
806 | 6 | dest: &str, |
807 | 6 | is_executable: bool, |
808 | 6 | custom_unix_mode: Option<u32>, |
809 | 6 | ) -> Result<(), Error> { |
810 | 6 | let mode2 = match (custom_unix_mode, is_executable) { |
811 | 1 | (Some(mode), true) => mode | 0o111, |
812 | 1 | (Some(mode), false) => mode, |
813 | 0 | (None, true) => 0o555, |
814 | 4 | (None, false) => return Ok(()), |
815 | | }; |
816 | 2 | fs::set_permissions(dest, Permissions::from_mode(mode)) |
817 | 2 | .await |
818 | 2 | .err_tip(|| format!0 ("Could not set unix mode in download_to_directory {dest}")) |
819 | 6 | } |
820 | | |
821 | | /// Non-unix has no mode to stamp. |
822 | | #[cfg(not(target_family = "unix"))] |
823 | | async fn stamp_unix_mode( |
824 | | _dest: &str, |
825 | | _is_executable: bool, |
826 | | _custom_unix_mode: Option<u32>, |
827 | | ) -> Result<(), Error> { |
828 | | Ok(()) |
829 | | } |
830 | | |
831 | | /// Materializes the nodes the batched passes cannot handle. |
832 | 28 | async fn materialize_inline_nodes( |
833 | 28 | cas_store: &FastSlowStore, |
834 | 28 | filesystem_store: Pin<&FilesystemStore>, |
835 | 28 | nodes: Vec<InlineNode>, |
836 | 28 | ) -> Result<(), Error> { |
837 | 28 | let mut futures = Vec::with_capacity(nodes.len()); |
838 | 28 | for node9 in nodes { |
839 | 9 | futures.push(async move { |
840 | 9 | match node { |
841 | | #[cfg(target_family = "unix")] |
842 | 3 | InlineNode::Symlink { target, dst } => fs::symlink(&target, &dst) |
843 | 3 | .await |
844 | 3 | .err_tip(|| format!0 ("Could not create symlink {target} -> {dst}")), |
845 | | InlineNode::File { |
846 | 6 | digest, |
847 | 6 | dst: dest, |
848 | 6 | is_executable, |
849 | 6 | mtime, |
850 | 6 | custom_unix_mode, |
851 | | } => { |
852 | 6 | cas_store.populate_fast_store(digest.into()).await?0 ; |
853 | 6 | async move { |
854 | 6 | if is_zero_digest(digest) { |
855 | | // Zero-digest files are never persisted by the |
856 | | // FilesystemStore, so materialise them directly in |
857 | | // the worker exec dir. |
858 | 4 | let mut file_slot = fs::create_file(&dest) |
859 | 4 | .await |
860 | 4 | .err_tip(|| format!0 ("Could not create zero-digest file at {dest}"))?0 ; |
861 | 4 | file_slot |
862 | 4 | .write_all(&[]) |
863 | 4 | .await |
864 | 4 | .err_tip(|| format!0 ("Could not write zero-digest file at {dest}"))?0 ; |
865 | | } else { |
866 | | // Rare path: per-file metadata (a custom unix_mode or |
867 | | // an mtime) must land on a PRIVATE inode. A |
868 | | // chmod/utimes on a hardlink mutates the shared CAS |
869 | | // inode for every other action that hardlinked it |
870 | | // (the #2347 corruption class). Copy the blob into a |
871 | | // private inode, then stamp mode/mtime onto it below. |
872 | 2 | let file_entry = filesystem_store |
873 | 2 | .get_file_entry_for_digest(&digest) |
874 | 2 | .await |
875 | 2 | .err_tip(|| "During private copy")?0 ; |
876 | 2 | let src_path = file_entry |
877 | 4 | .get_file_path_locked2 (|src| async move {2 Ok(src)2 }) |
878 | 2 | .await?0 ; |
879 | 2 | let spawned_dest = dest.clone(); |
880 | 2 | spawn_blocking!("download_to_directory_private_copy", move || { |
881 | 2 | std::fs::copy(&src_path, &spawned_dest).map(|_| ()).map_err(|e| {0 |
882 | 0 | make_err!( |
883 | 0 | Code::Internal, |
884 | | "Failed to copy CAS blob into a private inode at {spawned_dest}: {e:?}" |
885 | | ) |
886 | 0 | }) |
887 | 2 | }) |
888 | 2 | .await |
889 | 2 | .err_tip(|| {0 |
890 | 0 | "Failed to launch spawn_blocking private copy in download_to_directory" |
891 | 0 | })??; |
892 | | } |
893 | | |
894 | | // Private-inode tail (zero-digest or private copy only): |
895 | | // stamp the requested mode and mtime. Safe because the |
896 | | // inode is private to this action. |
897 | 6 | stamp_unix_mode(&dest, is_executable, custom_unix_mode).await?0 ; |
898 | 6 | if let Some(mtime2 ) = mtime { |
899 | 2 | let spawned_dest = dest.clone(); |
900 | 2 | spawn_blocking!("download_to_directory_set_mtime", move || { |
901 | 2 | set_file_mtime(&spawned_dest, mtime).err_tip(|| {0 |
902 | 0 | format!("Failed to set mtime in download_to_directory {spawned_dest}") |
903 | 0 | }) |
904 | 2 | }) |
905 | 2 | .await |
906 | 2 | .err_tip( |
907 | | || "Failed to launch spawn_blocking in download_to_directory", |
908 | 0 | )??; |
909 | 4 | } |
910 | 6 | Ok(()) |
911 | 6 | } |
912 | 6 | .await |
913 | 6 | .map_err(|e: Error| e0 .append0 (format!0 ("for digest {digest}"))) |
914 | | } |
915 | | } |
916 | 9 | }); |
917 | | } |
918 | 28 | futures::stream::iter(futures) |
919 | 28 | .buffer_unordered(DOWNLOAD_TO_DIRECTORY_CONCURRENCY) |
920 | 28 | .try_collect() |
921 | 28 | .await |
922 | 28 | } |
923 | | |
924 | | /// Prepares action inputs by first trying the directory cache (if available), |
925 | | /// then falling back to traditional `download_to_directory`. |
926 | | /// |
927 | | /// This provides a significant performance improvement for repeated builds |
928 | | /// with the same input directories. |
929 | | /// |
930 | | /// `work_directory` must already exist and be empty when this is called: the |
931 | | /// caller pre-creates it so that, on the fallback path, `download_to_directory` |
932 | | /// has a destination to write into. The directory cache, however, materializes |
933 | | /// the tree with `hardlink_directory_tree` / APFS `clonefile(2)`, both of which |
934 | | /// require the destination to *not* exist — so this function removes the empty |
935 | | /// directory before invoking the cache and recreates it if the cache fails. |
936 | 0 | pub async fn prepare_action_inputs( |
937 | 0 | directory_cache: &Option<Arc<crate::directory_cache::DirectoryCache>>, |
938 | 0 | cas_store: &FastSlowStore, |
939 | 0 | filesystem_store: Pin<&FilesystemStore>, |
940 | 0 | digest: &DigestInfo, |
941 | 0 | work_directory: &str, |
942 | 0 | ) -> Result<(), Error> { |
943 | | prepare_action_inputs_with_lease( |
944 | | directory_cache, |
945 | | cas_store, |
946 | | filesystem_store, |
947 | | digest, |
948 | | work_directory, |
949 | | None, |
950 | | ) |
951 | | .await |
952 | | } |
953 | | |
954 | 25 | async fn prepare_action_inputs_with_lease( |
955 | 25 | directory_cache: &Option<Arc<crate::directory_cache::DirectoryCache>>, |
956 | 25 | cas_store: &FastSlowStore, |
957 | 25 | filesystem_store: Pin<&FilesystemStore>, |
958 | 25 | digest: &DigestInfo, |
959 | 25 | work_directory: &str, |
960 | 25 | input_lease: Option<Arc<ActionInputLease>>, |
961 | 25 | ) -> Result<(), Error> { |
962 | | // Try cache first if available. Cache hits are safe while an action lease |
963 | | // is active because the directory cache pins its own materialized tree |
964 | | // across the hardlink operation. On a miss, pass the action lease into |
965 | | // cache construction so every CAS digest is reserved before it is |
966 | | // fetched/populated. |
967 | 25 | if let Some(cache2 ) = directory_cache { |
968 | | // `clonefile(2)` and `hardlink_directory_tree` both require the |
969 | | // destination to not exist. Remove the empty directory the caller |
970 | | // pre-created; without this the cache fails its precondition on every |
971 | | // action and silently falls back to the slow download path. |
972 | 2 | fs::remove_dir(work_directory) |
973 | 2 | .await |
974 | 2 | .err_tip(|| format!0 ("Failed to clear pre-created work directory {work_directory}"))?0 ; |
975 | 2 | let cache_result = if let Some(input_lease1 ) = &input_lease { |
976 | 1 | cache |
977 | 1 | .get_or_create_with_lease( |
978 | 1 | *digest, |
979 | 1 | Path::new(work_directory), |
980 | 1 | Some(input_lease.as_ref()), |
981 | 1 | ) |
982 | 1 | .await |
983 | | } else { |
984 | 1 | cache |
985 | 1 | .get_or_create(*digest, Path::new(work_directory)) |
986 | 1 | .await |
987 | | }; |
988 | 2 | match cache_result { |
989 | 2 | Ok(cache_hit) => { |
990 | | // The materialized tree is already usable. The directory |
991 | | // cache locks each entry down with `set_readonly_recursive`, |
992 | | // which leaves directories writable (0o755) and only makes |
993 | | // files read-only (0o555). The macOS `clonefile(2)` path |
994 | | // copies those modes verbatim and the Linux hardlink walk |
995 | | // creates fresh writable directories, so every directory in |
996 | | // the materialized tree already accepts the nested output |
997 | | // files Bazel actions declare — no separate per-materialize |
998 | | // recursive chmod walk is needed here. Files stay read-only, |
999 | | // preserving the hermeticity contract and the CAS-hardlink |
1000 | | // shared-inode invariant. |
1001 | 2 | trace!( |
1002 | | ?digest, |
1003 | | work_directory, cache_hit, "Successfully prepared inputs via directory cache" |
1004 | | ); |
1005 | 2 | return Ok(()); |
1006 | | } |
1007 | 0 | Err(e) => { |
1008 | 0 | warn!( |
1009 | | ?digest, |
1010 | | ?e, |
1011 | | "Directory cache failed, falling back to traditional download" |
1012 | | ); |
1013 | | // The cache may have materialized a partial tree before |
1014 | | // failing. `download_to_directory` needs an existing, empty |
1015 | | // destination, so discard any partial state and recreate the |
1016 | | // work directory. |
1017 | 0 | let _cleanup = fs::remove_dir_all(work_directory).await; |
1018 | 0 | fs::create_dir(work_directory) |
1019 | 0 | .await |
1020 | 0 | .err_tip(|| format!("Failed to recreate work directory {work_directory}"))?; |
1021 | | } |
1022 | | } |
1023 | 23 | } |
1024 | | |
1025 | | // Traditional path (cache disabled or failed) |
1026 | 23 | download_to_directory_with_lease( |
1027 | 23 | cas_store, |
1028 | 23 | filesystem_store, |
1029 | 23 | digest, |
1030 | 23 | work_directory, |
1031 | 23 | input_lease, |
1032 | 23 | ) |
1033 | 23 | .await |
1034 | 25 | } |
1035 | | |
1036 | | #[cfg(target_family = "windows")] |
1037 | | fn is_executable(_metadata: &std::fs::Metadata, full_path: &impl AsRef<Path>) -> bool { |
1038 | | static EXECUTABLE_EXTENSIONS: &[&str] = &["exe", "bat", "com"]; |
1039 | | EXECUTABLE_EXTENSIONS |
1040 | | .iter() |
1041 | | .any(|ext| full_path.as_ref().extension().map_or(false, |v| v == *ext)) |
1042 | | } |
1043 | | |
1044 | | #[cfg(target_family = "unix")] |
1045 | 16 | fn is_executable(metadata: &std::fs::Metadata, _full_path: &impl AsRef<Path>) -> bool { |
1046 | 16 | (metadata.mode() & 0o111) != 0 |
1047 | 16 | } |
1048 | | |
1049 | | type DigestUploader = Arc<tokio::sync::OnceCell<()>>; |
1050 | | |
1051 | 16 | async fn upload_file( |
1052 | 16 | cas_store: Pin<&impl StoreLike>, |
1053 | 16 | full_path: impl AsRef<Path> + Debug + Send + Sync, |
1054 | 16 | hasher: DigestHasherFunc, |
1055 | 16 | metadata: std::fs::Metadata, |
1056 | 16 | digest_uploaders: Arc<Mutex<HashMap<DigestInfo, DigestUploader>>>, |
1057 | 16 | ) -> Result<FileInfo, Error> { |
1058 | 16 | let is_executable = is_executable(&metadata, &full_path); |
1059 | 16 | let file_size = metadata.len(); |
1060 | 16 | let file = fs::open_file(&full_path, 0, u64::MAX) |
1061 | 16 | .await |
1062 | 16 | .err_tip(|| format!0 ("Could not open file {full_path:?}"))?0 ; |
1063 | | |
1064 | 16 | let (digest, mut file) = hasher |
1065 | 16 | .hasher() |
1066 | 16 | .digest_for_file(&full_path, file.into_inner(), Some(file_size)) |
1067 | 16 | .await |
1068 | 16 | .err_tip(|| format!0 ("Failed to hash file in digest_for_file failed for {full_path:?}"))?0 ; |
1069 | | |
1070 | 16 | let digest_uploader = match digest_uploaders.lock().entry(digest) { |
1071 | 1 | std::collections::hash_map::Entry::Occupied(occupied_entry) => occupied_entry.get().clone(), |
1072 | 15 | std::collections::hash_map::Entry::Vacant(vacant_entry) => vacant_entry |
1073 | 15 | .insert(Arc::new(tokio::sync::OnceCell::new())) |
1074 | 15 | .clone(), |
1075 | | }; |
1076 | | |
1077 | | // Only upload a file with a given hash once. The file may exist multiple |
1078 | | // times in the output with different names. |
1079 | 16 | digest_uploader |
1080 | 30 | .get_or_try_init16 (async || { |
1081 | | // Only upload if the digest doesn't already exist, this should be |
1082 | | // a much cheaper operation than an upload. |
1083 | 15 | let cas_store = cas_store.as_store_driver_pin(); |
1084 | 15 | let store_key: nativelink_util::store_trait::StoreKey<'_> = digest.into(); |
1085 | 15 | let has_start = std::time::Instant::now(); |
1086 | 15 | if cas_store |
1087 | 15 | .has(store_key.borrow()) |
1088 | 15 | .await |
1089 | 15 | .is_ok_and(|result| result.is_some()) |
1090 | | { |
1091 | 2 | trace!( |
1092 | | ?digest, |
1093 | 2 | has_elapsed_ms = has_start.elapsed().as_millis(), |
1094 | | "upload_file: digest already exists in CAS, skipping upload", |
1095 | | ); |
1096 | 2 | return Ok(()); |
1097 | 13 | } |
1098 | 13 | trace!( |
1099 | | ?digest, |
1100 | 13 | has_elapsed_ms = has_start.elapsed().as_millis(), |
1101 | 13 | file_size = digest.size_bytes(), |
1102 | | "upload_file: digest not in CAS, starting upload", |
1103 | | ); |
1104 | | |
1105 | 13 | file.rewind().await.err_tip(|| "Could not rewind file")?0 ; |
1106 | | |
1107 | | // Note: For unknown reasons we appear to be hitting: |
1108 | | // https://github.com/rust-lang/rust/issues/92096 |
1109 | | // or a similar issue if we try to use the non-store driver function, so we |
1110 | | // are using the store driver function here. |
1111 | 13 | let store_key_for_upload = store_key.clone(); |
1112 | 13 | let file_upload_start = std::time::Instant::now(); |
1113 | 13 | let upload_result = cas_store |
1114 | 13 | .update_with_whole_file( |
1115 | 13 | store_key_for_upload, |
1116 | 13 | full_path.as_ref().into(), |
1117 | 13 | file, |
1118 | 13 | UploadSizeInfo::ExactSize(digest.size_bytes()), |
1119 | 13 | ) |
1120 | 13 | .await |
1121 | 13 | .map(|_slot| ()); |
1122 | 13 | trace!( |
1123 | | ?digest, |
1124 | 13 | upload_elapsed_ms = file_upload_start.elapsed().as_millis(), |
1125 | 13 | success = upload_result.is_ok(), |
1126 | | "upload_file: update_with_whole_file completed", |
1127 | | ); |
1128 | | |
1129 | 13 | match upload_result { |
1130 | 13 | Ok(()) => Ok(()), |
1131 | 0 | Err(err) => { |
1132 | | // Output uploads run concurrently and may overlap (e.g. a file is listed |
1133 | | // both as an output file and inside an output directory). When another |
1134 | | // upload has already moved the file into CAS, this update can fail with |
1135 | | // NotFound even though the digest is now present. Per the RE spec, missing |
1136 | | // outputs should be ignored, so treat this as success if the digest exists. |
1137 | 0 | if err.code == Code::NotFound |
1138 | 0 | && cas_store |
1139 | 0 | .has(store_key.borrow()) |
1140 | 0 | .await |
1141 | 0 | .is_ok_and(|result| result.is_some()) |
1142 | | { |
1143 | 0 | Ok(()) |
1144 | | } else { |
1145 | 0 | Err(err) |
1146 | | } |
1147 | | } |
1148 | | } |
1149 | 30 | }) |
1150 | 16 | .await |
1151 | 16 | .err_tip(|| format!0 ("for {full_path:?}"))?0 ; |
1152 | | |
1153 | 16 | let name = full_path |
1154 | 16 | .as_ref() |
1155 | 16 | .file_name() |
1156 | 16 | .err_tip(|| format!0 ("Expected file_name to exist on {full_path:?}"))?0 |
1157 | 16 | .to_str() |
1158 | 16 | .err_tip(|| {0 |
1159 | 0 | make_err!( |
1160 | 0 | Code::Internal, |
1161 | | "Could not convert {:?} to string", |
1162 | | full_path |
1163 | | ) |
1164 | 0 | })? |
1165 | 16 | .to_string(); |
1166 | | |
1167 | 16 | Ok(FileInfo { |
1168 | 16 | name_or_path: NameOrPath::Name(name), |
1169 | 16 | digest, |
1170 | 16 | is_executable, |
1171 | 16 | }) |
1172 | 16 | } |
1173 | | |
1174 | 2 | async fn upload_symlink( |
1175 | 2 | full_path: impl AsRef<Path> + Debug, |
1176 | 2 | full_work_directory_path: impl AsRef<Path>, |
1177 | 2 | ) -> Result<SymlinkInfo, Error> { |
1178 | 2 | let full_target_path = fs::read_link(full_path.as_ref()) |
1179 | 2 | .await |
1180 | 2 | .err_tip(|| format!0 ("Could not get read_link path of {full_path:?}"))?0 ; |
1181 | | |
1182 | | // Detect if our symlink is inside our work directory, if it is find the |
1183 | | // relative path otherwise use the absolute path. |
1184 | 2 | let target = if full_target_path.starts_with(full_work_directory_path.as_ref()) { |
1185 | 0 | let full_target_path = RelativePath::from_path(&full_target_path) |
1186 | 0 | .map_err(|v| make_err!(Code::Internal, "Could not convert {} to RelativePath", v))?; |
1187 | 0 | RelativePath::from_path(full_work_directory_path.as_ref()) |
1188 | 0 | .map_err(|v| make_err!(Code::Internal, "Could not convert {} to RelativePath", v))? |
1189 | 0 | .relative(full_target_path) |
1190 | 0 | .normalize() |
1191 | 0 | .into_string() |
1192 | | } else { |
1193 | 2 | full_target_path |
1194 | 2 | .to_str() |
1195 | 2 | .err_tip(|| {0 |
1196 | 0 | make_err!( |
1197 | 0 | Code::Internal, |
1198 | | "Could not convert '{:?}' to string", |
1199 | | full_target_path |
1200 | | ) |
1201 | 0 | })? |
1202 | 2 | .to_string() |
1203 | | }; |
1204 | | |
1205 | 2 | let name = full_path |
1206 | 2 | .as_ref() |
1207 | 2 | .file_name() |
1208 | 2 | .err_tip(|| format!0 ("Expected file_name to exist on {full_path:?}"))?0 |
1209 | 2 | .to_str() |
1210 | 2 | .err_tip(|| {0 |
1211 | 0 | make_err!( |
1212 | 0 | Code::Internal, |
1213 | | "Could not convert {:?} to string", |
1214 | | full_path |
1215 | | ) |
1216 | 0 | })? |
1217 | 2 | .to_string(); |
1218 | | |
1219 | 2 | Ok(SymlinkInfo { |
1220 | 2 | name_or_path: NameOrPath::Name(name), |
1221 | 2 | target, |
1222 | 2 | }) |
1223 | 2 | } |
1224 | | |
1225 | 7 | fn upload_directory<'a, P: AsRef<Path> + Debug + Send + Sync + Clone + 'a>( |
1226 | 7 | cas_store: Pin<&'a impl StoreLike>, |
1227 | 7 | full_dir_path: P, |
1228 | 7 | full_work_directory: &'a str, |
1229 | 7 | hasher: DigestHasherFunc, |
1230 | 7 | digest_uploaders: Arc<Mutex<HashMap<DigestInfo, DigestUploader>>>, |
1231 | 7 | ) -> BoxFuture<'a, Result<(Directory, VecDeque<ProtoDirectory>), Error>> { |
1232 | 7 | Box::pin(async move { |
1233 | 7 | let file_futures = FuturesUnordered::new(); |
1234 | 7 | let dir_futures = FuturesUnordered::new(); |
1235 | 7 | let symlink_futures = FuturesUnordered::new(); |
1236 | | { |
1237 | 7 | let (_permit, dir_handle) = fs::read_dir(&full_dir_path) |
1238 | 7 | .await |
1239 | 7 | .err_tip(|| format!0 ("Error reading dir for reading {full_dir_path:?}"))?0 |
1240 | 7 | .into_inner(); |
1241 | 7 | let mut dir_stream = ReadDirStream::new(dir_handle); |
1242 | | // Note: Try very hard to not leave file descriptors open. Try to keep them as short |
1243 | | // lived as possible. This is why we iterate the directory and then build a bunch of |
1244 | | // futures with all the work we are wanting to do then execute it. It allows us to |
1245 | | // close the directory iterator file descriptor, then open the child files/folders. |
1246 | 18 | while let Some(entry_result11 ) = dir_stream.next().await { |
1247 | 11 | let entry = entry_result.err_tip(|| "Error while iterating directory")?0 ; |
1248 | 11 | let file_type = entry |
1249 | 11 | .file_type() |
1250 | 11 | .await |
1251 | 11 | .err_tip(|| format!0 ("Error running file_type() on {entry:?}"))?0 ; |
1252 | 11 | let full_path = full_dir_path.as_ref().join(entry.path()); |
1253 | 11 | if file_type.is_dir() { |
1254 | 3 | let full_dir_path = full_dir_path.clone(); |
1255 | 3 | dir_futures.push( |
1256 | 3 | upload_directory( |
1257 | 3 | cas_store, |
1258 | 3 | full_path.clone(), |
1259 | 3 | full_work_directory, |
1260 | 3 | hasher, |
1261 | 3 | digest_uploaders.clone(), |
1262 | | ) |
1263 | 3 | .and_then(|(dir, all_dirs)| async move { |
1264 | 3 | let directory_name = full_path |
1265 | 3 | .file_name() |
1266 | 3 | .err_tip(|| {0 |
1267 | 0 | format!("Expected file_name to exist on {full_dir_path:?}") |
1268 | 0 | })? |
1269 | 3 | .to_str() |
1270 | 3 | .err_tip(|| {0 |
1271 | 0 | make_err!( |
1272 | 0 | Code::Internal, |
1273 | | "Could not convert {:?} to string", |
1274 | | full_dir_path |
1275 | | ) |
1276 | 0 | })? |
1277 | 3 | .to_string(); |
1278 | | |
1279 | 3 | let digest = |
1280 | 3 | serialize_and_upload_message(&dir, cas_store, &mut hasher.hasher()) |
1281 | 3 | .await |
1282 | 3 | .err_tip(|| format!0 ("for {}", full_path.display()0 ))?0 ; |
1283 | | |
1284 | 3 | Result::<(DirectoryNode, VecDeque<Directory>), Error>::Ok(( |
1285 | 3 | DirectoryNode { |
1286 | 3 | name: directory_name, |
1287 | 3 | digest: Some(digest.into()), |
1288 | 3 | }, |
1289 | 3 | all_dirs, |
1290 | 3 | )) |
1291 | 6 | }) |
1292 | 3 | .boxed(), |
1293 | | ); |
1294 | 8 | } else if file_type.is_file() { |
1295 | 7 | let digest_uploaders = digest_uploaders.clone(); |
1296 | 7 | file_futures.push(async move { |
1297 | 7 | let metadata = fs::metadata(&full_path) |
1298 | 7 | .await |
1299 | 7 | .err_tip(|| format!0 ("Could not open file {}", full_path.display()0 ))?0 ; |
1300 | 7 | upload_file(cas_store, &full_path, hasher, metadata, digest_uploaders) |
1301 | 7 | .map_ok(TryInto::try_into) |
1302 | 7 | .await?0 |
1303 | 7 | }); |
1304 | 1 | } else if file_type.is_symlink() { |
1305 | 1 | symlink_futures.push( |
1306 | 1 | upload_symlink(full_path, &full_work_directory) |
1307 | 1 | .map(|symlink| symlink?0 .try_into()), |
1308 | | ); |
1309 | 0 | } |
1310 | | } |
1311 | | } |
1312 | | |
1313 | 7 | let dir_entries = dir_futures |
1314 | 7 | .try_collect::<Vec<(DirectoryNode, VecDeque<Directory>)>>() |
1315 | 7 | .await?0 ; |
1316 | 7 | let (mut file_nodes, mut symlinks) = try_join( |
1317 | 7 | file_futures.try_collect::<Vec<FileNode>>(), |
1318 | 7 | symlink_futures.try_collect::<Vec<SymlinkNode>>(), |
1319 | 7 | ) |
1320 | 7 | .await?0 ; |
1321 | | |
1322 | 7 | let mut directory_nodes = Vec::with_capacity(dir_entries.len()); |
1323 | | // For efficiency we use a deque because it allows cheap concat of Vecs. |
1324 | | // We make the assumption here that when performance is important it is because |
1325 | | // our directory is quite large. This allows us to cheaply merge large amounts of |
1326 | | // directories into one VecDeque. Then after we are done we need to collapse it |
1327 | | // down into a single Vec. |
1328 | 7 | let mut all_child_directories = VecDeque::with_capacity(dir_entries.len()); |
1329 | 7 | for (directory_node3 , mut recursive_child_directories3 ) in dir_entries { |
1330 | 3 | directory_nodes.push(directory_node); |
1331 | 3 | all_child_directories.append(&mut recursive_child_directories); |
1332 | 3 | } |
1333 | | |
1334 | 7 | file_nodes.sort_unstable_by(|a, b| a.name1 .cmp1 (&b.name1 )); |
1335 | 7 | directory_nodes.sort_unstable_by(|a, b| a.name0 .cmp0 (&b.name0 )); |
1336 | 7 | symlinks.sort_unstable_by(|a, b| a.name0 .cmp0 (&b.name0 )); |
1337 | | |
1338 | 7 | let directory = Directory { |
1339 | 7 | files: file_nodes, |
1340 | 7 | directories: directory_nodes, |
1341 | 7 | symlinks, |
1342 | 7 | node_properties: None, // We don't support file properties. |
1343 | 7 | }; |
1344 | 7 | all_child_directories.push_back(directory.clone()); |
1345 | | |
1346 | 7 | Ok((directory, all_child_directories)) |
1347 | 7 | }) |
1348 | 7 | } |
1349 | | |
1350 | 0 | async fn process_side_channel_file( |
1351 | 0 | side_channel_file: Cow<'_, OsStr>, |
1352 | 0 | args: &[&OsStr], |
1353 | 0 | timeout: Duration, |
1354 | 0 | ) -> Result<Option<Error>, Error> { |
1355 | 0 | let mut json_contents = String::new(); |
1356 | | { |
1357 | | // Note: Scoping `file_slot` allows the file_slot semaphore to be released faster. |
1358 | 0 | let mut file_slot = match fs::open_file(side_channel_file, 0, u64::MAX).await { |
1359 | 0 | Ok(file_slot) => file_slot, |
1360 | 0 | Err(e) => { |
1361 | 0 | if e.code != Code::NotFound { |
1362 | 0 | return Err(e).err_tip(|| "Error opening side channel file"); |
1363 | 0 | } |
1364 | | // Note: If file does not exist, it's ok. Users are not required to create this file. |
1365 | 0 | return Ok(None); |
1366 | | } |
1367 | | }; |
1368 | 0 | file_slot |
1369 | 0 | .read_to_string(&mut json_contents) |
1370 | 0 | .await |
1371 | 0 | .err_tip(|| "Error reading side channel file")?; |
1372 | | } |
1373 | | |
1374 | 0 | let side_channel_info: SideChannelInfo = serde_json5::from_str(&json_contents) |
1375 | 0 | .map_err(Error::from) |
1376 | 0 | .err_tip(|| "Could not convert contents of side channel file (json) to SideChannelInfo")?; |
1377 | 0 | Ok(side_channel_info.failure.map(|failure| match failure { |
1378 | | SideChannelFailureReason::Timeout => { |
1379 | 0 | let join_args = args.join(OsStr::new(" ")); |
1380 | 0 | let command = join_args.to_string_lossy(); |
1381 | 0 | warn!(%command, timeout=timeout.as_secs_f32(), "Side channel timeout for command"); |
1382 | 0 | Error::new( |
1383 | 0 | Code::DeadlineExceeded, |
1384 | 0 | format!( |
1385 | | "Command '{}' timed out after {} seconds", |
1386 | | command, |
1387 | 0 | timeout.as_secs_f32() |
1388 | | ), |
1389 | | ) |
1390 | | } |
1391 | 0 | })) |
1392 | 0 | } |
1393 | | |
1394 | 226 | async fn do_cleanup( |
1395 | 226 | running_actions_manager: &Arc<RunningActionsManagerImpl>, |
1396 | 226 | operation_id: &OperationId, |
1397 | 226 | action_directory: &str, |
1398 | 226 | ) -> Result<(), Error> { |
1399 | | // Mark this operation as being cleaned up |
1400 | 226 | let Some(_cleaning_guard) = running_actions_manager.perform_cleanup(operation_id.clone()) |
1401 | | else { |
1402 | | // Cleanup is already happening elsewhere. |
1403 | 0 | return Ok(()); |
1404 | | }; |
1405 | | |
1406 | 226 | debug!("Worker cleaning up"); |
1407 | | // Note: We need to be careful to keep trying to cleanup even if one of the steps fails. |
1408 | 226 | let remove_dir_result = fs::remove_dir_all(action_directory) |
1409 | 226 | .await |
1410 | 226 | .err_tip(|| format!0 ("Could not remove working directory {action_directory}")); |
1411 | | |
1412 | 226 | if let Err(err0 ) = running_actions_manager.cleanup_action(operation_id) { |
1413 | 0 | error!(%operation_id, ?err, "Error cleaning up action"); |
1414 | 0 | Result::<(), Error>::Err(err).merge(remove_dir_result) |
1415 | 226 | } else if let Err(err0 ) = remove_dir_result { |
1416 | 0 | error!(%operation_id, ?err, "Error removing working directory"); |
1417 | 0 | Err(err) |
1418 | | } else { |
1419 | 226 | Ok(()) |
1420 | | } |
1421 | 226 | } |
1422 | | |
1423 | | pub trait RunningAction: Sync + Send + Sized + Unpin + 'static { |
1424 | | /// Returns the action id of the action. |
1425 | | fn get_operation_id(&self) -> &OperationId; |
1426 | | |
1427 | | /// Anything that needs to execute before the actions is actually executed should happen here. |
1428 | | fn prepare_action(self: Arc<Self>) -> impl Future<Output = Result<Arc<Self>, Error>> + Send; |
1429 | | |
1430 | | /// Actually perform the execution of the action. |
1431 | | fn execute(self: Arc<Self>) -> impl Future<Output = Result<Arc<Self>, Error>> + Send; |
1432 | | |
1433 | | /// Any uploading, processing or analyzing of the results should happen here. |
1434 | | fn upload_results(self: Arc<Self>) -> impl Future<Output = Result<Arc<Self>, Error>> + Send; |
1435 | | |
1436 | | /// Cleanup any residual files, handles or other junk resulting from running the action. |
1437 | | fn cleanup(self: Arc<Self>) -> impl Future<Output = Result<Arc<Self>, Error>> + Send; |
1438 | | |
1439 | | /// Returns the final result. As a general rule this action should be thought of as |
1440 | | /// a consumption of `self`, meaning once a return happens here the lifetime of `Self` |
1441 | | /// is over and any action performed on it after this call is undefined behavior. |
1442 | | fn get_finished_result( |
1443 | | self: Arc<Self>, |
1444 | | ) -> impl Future<Output = Result<ActionResult, Error>> + Send; |
1445 | | |
1446 | | /// Returns worker-observed resource usage captured while this action ran. |
1447 | | fn resource_usage(&self) -> Option<ActionResourceUsage>; |
1448 | | |
1449 | | /// Returns the work directory of the action. |
1450 | | fn get_work_directory(&self) -> &String; |
1451 | | } |
1452 | | |
1453 | | #[derive(Debug)] |
1454 | | struct RunningActionImplExecutionResult { |
1455 | | stdout: Bytes, |
1456 | | stderr: Bytes, |
1457 | | exit_code: i32, |
1458 | | resource_usage: Option<ActionResourceUsage>, |
1459 | | } |
1460 | | |
1461 | | #[derive(Debug)] |
1462 | | struct RunningActionImplState { |
1463 | | command_proto: Option<ProtoCommand>, |
1464 | | // TODO(palfrey) Kill is not implemented yet, but is instrumented. |
1465 | | // However, it is used if the worker disconnects to destroy current jobs. |
1466 | | kill_channel_tx: Option<oneshot::Sender<()>>, |
1467 | | kill_channel_rx: Option<oneshot::Receiver<()>>, |
1468 | | execution_result: Option<RunningActionImplExecutionResult>, |
1469 | | action_result: Option<ActionResult>, |
1470 | | resource_usage: Option<ActionResourceUsage>, |
1471 | | execution_metadata: ExecutionMetadata, |
1472 | | // If there was an internal error, this will be set. |
1473 | | // This should NOT be set if everything was fine, but the process had a |
1474 | | // non-zero exit code. Instead this should be used for internal errors |
1475 | | // that prevented the action from running, upload failures, timeouts, exc... |
1476 | | // but we have (or could have) the action results (like stderr/stdout). |
1477 | | error: Option<Error>, |
1478 | | } |
1479 | | |
1480 | | #[derive(Debug)] |
1481 | | pub struct RunningActionImpl { |
1482 | | operation_id: OperationId, |
1483 | | action_directory: String, |
1484 | | work_directory: String, |
1485 | | action_info: ActionInfo, |
1486 | | /// `Some` only when the manager was configured with |
1487 | | /// `experimental_active_input_leases`; `None` leaves eviction untouched. |
1488 | | input_lease: Option<Arc<ActionInputLease>>, |
1489 | | timeout: Duration, |
1490 | | running_actions_manager: Arc<RunningActionsManagerImpl>, |
1491 | | state: Mutex<RunningActionImplState>, |
1492 | | has_manager_entry: AtomicBool, |
1493 | | did_cleanup: AtomicBool, |
1494 | | } |
1495 | | |
1496 | | impl RunningActionImpl { |
1497 | 229 | pub fn new( |
1498 | 229 | execution_metadata: ExecutionMetadata, |
1499 | 229 | operation_id: OperationId, |
1500 | 229 | action_directory: String, |
1501 | 229 | action_info: ActionInfo, |
1502 | 229 | timeout: Duration, |
1503 | 229 | running_actions_manager: Arc<RunningActionsManagerImpl>, |
1504 | 229 | ) -> Self { |
1505 | 229 | let work_directory = format!("{}/{}", action_directory, "work"); |
1506 | 229 | let input_lease = running_actions_manager.active_input_leases.then(|| {1 |
1507 | 1 | ActionInputLease::new( |
1508 | 1 | running_actions_manager.cas_store.as_ref(), |
1509 | 1 | action_info.command_digest, |
1510 | 1 | action_info.input_root_digest, |
1511 | | ) |
1512 | 1 | }); |
1513 | 229 | let (kill_channel_tx, kill_channel_rx) = oneshot::channel(); |
1514 | 229 | Self { |
1515 | 229 | operation_id, |
1516 | 229 | action_directory, |
1517 | 229 | work_directory, |
1518 | 229 | action_info, |
1519 | 229 | input_lease, |
1520 | 229 | timeout, |
1521 | 229 | running_actions_manager, |
1522 | 229 | state: Mutex::new(RunningActionImplState { |
1523 | 229 | command_proto: None, |
1524 | 229 | kill_channel_rx: Some(kill_channel_rx), |
1525 | 229 | kill_channel_tx: Some(kill_channel_tx), |
1526 | 229 | execution_result: None, |
1527 | 229 | action_result: None, |
1528 | 229 | resource_usage: None, |
1529 | 229 | execution_metadata, |
1530 | 229 | error: None, |
1531 | 229 | }), |
1532 | 229 | // Set to true only after the action is inserted into the manager. |
1533 | 229 | // The constructor can fail the operation-id uniqueness check |
1534 | 229 | // immediately after this object is created. |
1535 | 229 | has_manager_entry: AtomicBool::new(false), |
1536 | 229 | // Only needs to be cleaned up after a prepare_action call, set there. |
1537 | 229 | did_cleanup: AtomicBool::new(true), |
1538 | 229 | } |
1539 | 229 | } |
1540 | | |
1541 | | #[allow( |
1542 | | clippy::missing_const_for_fn, |
1543 | | reason = "False positive on stable, but not on nightly" |
1544 | | )] |
1545 | 0 | fn metrics(&self) -> &Arc<Metrics> { |
1546 | 0 | &self.running_actions_manager.metrics |
1547 | 0 | } |
1548 | | |
1549 | | /// Prepares any actions needed to execute this action. This action will do the following: |
1550 | | /// |
1551 | | /// * Download any files needed to execute the action |
1552 | | /// * Build a folder with all files needed to execute the action. |
1553 | | /// |
1554 | | /// This function will aggressively download and spawn potentially thousands of futures. It is |
1555 | | /// up to the stores to rate limit if needed. |
1556 | 25 | async fn inner_prepare_action(self: Arc<Self>) -> Result<Arc<Self>, Error> { |
1557 | 25 | { |
1558 | 25 | let mut state = self.state.lock(); |
1559 | 25 | state.execution_metadata.input_fetch_start_timestamp = |
1560 | 25 | (self.running_actions_manager.callbacks.now_fn)(); |
1561 | 25 | } |
1562 | 25 | let command = { |
1563 | | // Download and build out our input files/folders. Also fetch and decode our Command. |
1564 | 25 | let command_fut = self.metrics().get_proto_command_from_store.wrap(async { |
1565 | 25 | get_and_decode_digest::<ProtoCommand>( |
1566 | 25 | self.running_actions_manager.cas_store.as_ref(), |
1567 | 25 | self.action_info.command_digest.into(), |
1568 | 25 | ) |
1569 | 25 | .await |
1570 | 25 | .err_tip(|| "Converting command_digest to Command") |
1571 | 25 | }); |
1572 | 25 | let filesystem_store_pin = |
1573 | 25 | Pin::new(self.running_actions_manager.filesystem_store.as_ref()); |
1574 | 25 | let (command, ()) = try_join(command_fut, async { |
1575 | 25 | fs::create_dir(&self.work_directory) |
1576 | 25 | .await |
1577 | 25 | .err_tip(|| format!0 ("Error creating work directory {}", self.work_directory0 ))?0 ; |
1578 | | // Now the work directory has been created, we have to clean up. |
1579 | 25 | self.did_cleanup.store(false, Ordering::Release); |
1580 | | // Download the input files/folder and place them into the temp directory. |
1581 | | // Use directory cache if available for better performance. |
1582 | 25 | self.metrics() |
1583 | 25 | .download_to_directory |
1584 | 25 | .wrap(prepare_action_inputs_with_lease( |
1585 | 25 | &self.running_actions_manager.directory_cache, |
1586 | 25 | &self.running_actions_manager.cas_store, |
1587 | 25 | filesystem_store_pin, |
1588 | 25 | &self.action_info.input_root_digest, |
1589 | 25 | &self.work_directory, |
1590 | 25 | self.input_lease.clone(), |
1591 | 25 | )) |
1592 | 25 | .await |
1593 | 25 | }) |
1594 | 25 | .await?0 ; |
1595 | 25 | command |
1596 | | }; |
1597 | | { |
1598 | | // Create all directories needed for our output paths. This is required by the bazel spec. |
1599 | 25 | let prepare_output_directories = |output_file| {16 |
1600 | 16 | let full_output_path = if command.working_directory.is_empty() { |
1601 | 4 | format!("{}/{}", self.work_directory, output_file) |
1602 | | } else { |
1603 | 12 | format!( |
1604 | | "{}/{}/{}", |
1605 | 12 | self.work_directory, command.working_directory, output_file |
1606 | | ) |
1607 | | }; |
1608 | 16 | async move { |
1609 | 16 | let full_parent_path = Path::new(&full_output_path) |
1610 | 16 | .parent() |
1611 | 16 | .err_tip(|| format!0 ("Parent path for {full_output_path} has no parent"))?0 ; |
1612 | 16 | fs::create_dir_all(full_parent_path).await.err_tip(|| {0 |
1613 | 0 | format!( |
1614 | | "Error creating output directory {} (file)", |
1615 | 0 | full_parent_path.display() |
1616 | | ) |
1617 | 0 | })?; |
1618 | 16 | Result::<(), Error>::Ok(()) |
1619 | 16 | } |
1620 | 16 | }; |
1621 | 25 | self.metrics() |
1622 | 25 | .prepare_output_files |
1623 | 25 | .wrap(try_join_all( |
1624 | 25 | command.output_files.iter().map(prepare_output_directories), |
1625 | 25 | )) |
1626 | 25 | .await?0 ; |
1627 | 25 | self.metrics() |
1628 | 25 | .prepare_output_paths |
1629 | 25 | .wrap(try_join_all( |
1630 | 25 | command.output_paths.iter().map(prepare_output_directories), |
1631 | 25 | )) |
1632 | 25 | .await?0 ; |
1633 | | } |
1634 | 25 | debug!(?command, "Worker received command"); |
1635 | 25 | { |
1636 | 25 | let mut state = self.state.lock(); |
1637 | 25 | state.command_proto = Some(command); |
1638 | 25 | state.execution_metadata.input_fetch_completed_timestamp = |
1639 | 25 | (self.running_actions_manager.callbacks.now_fn)(); |
1640 | 25 | } |
1641 | 25 | Ok(self) |
1642 | 25 | } |
1643 | | |
1644 | 22 | pub fn canonicalise_path( |
1645 | 22 | self: &Arc<Self>, |
1646 | 22 | arg: &OsStr, |
1647 | 22 | working_directory: &String, |
1648 | 22 | ) -> Result<PathBuf, Error> { |
1649 | | // If the program contains a slash, we treat it as a path and resolve it relative to the work directory. |
1650 | 22 | Ok(if Path::new(arg).components().count() > 1 { |
1651 | 5 | let canonical_path = PathBuf::from(&self.work_directory) |
1652 | 5 | .join(working_directory) |
1653 | 5 | .join(arg); |
1654 | 5 | if cfg!(target_os = "windows") { |
1655 | | // Workaround for https://github.com/rust-lang/rust/issues/42869 using a windows-specific crate |
1656 | 0 | dunce::canonicalize(canonical_path) |
1657 | | } else { |
1658 | 5 | canonical_path.canonicalize() |
1659 | | } |
1660 | 5 | .err_tip(|| {1 |
1661 | 1 | format!( |
1662 | | "Could not canonicalize path for command root {}.", |
1663 | 1 | arg.to_string_lossy() |
1664 | | ) |
1665 | 1 | })? |
1666 | | } else { |
1667 | 17 | PathBuf::from(arg) |
1668 | | }) |
1669 | 22 | } |
1670 | | |
1671 | 21 | async fn inner_execute(self: Arc<Self>) -> Result<Arc<Self>, Error> { |
1672 | 21 | let (command_proto, mut kill_channel_rx) = { |
1673 | 21 | let mut state = self.state.lock(); |
1674 | 21 | state.execution_metadata.execution_start_timestamp = |
1675 | 21 | (self.running_actions_manager.callbacks.now_fn)(); |
1676 | | ( |
1677 | 21 | state |
1678 | 21 | .command_proto |
1679 | 21 | .take() |
1680 | 21 | .err_tip(|| "Expected state to have command_proto in execute()")?0 , |
1681 | 21 | state |
1682 | 21 | .kill_channel_rx |
1683 | 21 | .take() |
1684 | 21 | .err_tip(|| "Expected state to have kill_channel_rx in execute()")?0 |
1685 | | // This is important as we may be killed at any point. |
1686 | 21 | .fuse(), |
1687 | | ) |
1688 | | }; |
1689 | 21 | if command_proto.arguments.is_empty() { |
1690 | 0 | return Err(make_input_err!("No arguments provided in Command proto")); |
1691 | 21 | } |
1692 | 21 | let args: Vec<&OsStr> = if let Some(entrypoint0 ) = &self |
1693 | 21 | .running_actions_manager |
1694 | 21 | .execution_configuration |
1695 | 21 | .entrypoint |
1696 | | { |
1697 | 0 | core::iter::once(entrypoint.as_ref()) |
1698 | 0 | .chain(command_proto.arguments.iter().map(AsRef::as_ref)) |
1699 | 0 | .collect() |
1700 | | } else { |
1701 | 21 | command_proto.arguments.iter().map(AsRef::as_ref).collect() |
1702 | | }; |
1703 | | // TODO(palfrey): This should probably be in debug, but currently |
1704 | | // that's too busy and we often rely on this to |
1705 | | // figure out toolchain misconfiguration issues. |
1706 | | // De-bloat the `debug` level by using the `trace` |
1707 | | // level more effectively and adjust this. |
1708 | 21 | info!(?args, "Executing command"); |
1709 | | |
1710 | 21 | let program20 = self |
1711 | 21 | .canonicalise_path(args[0], &command_proto.working_directory) |
1712 | 21 | .err_tip(|| format!1 ("Canonicalisation failure. Command={args:#?}"))?1 ; |
1713 | 20 | if let Some(wire_format_result2 ) = action_supports_persistent_workers(&self.action_info) { |
1714 | 2 | match wire_format_result { |
1715 | 2 | Ok(wire_format) => { |
1716 | 2 | let command_argv = os_args_to_strings(&args)?0 ; |
1717 | 2 | let key = WorkerKey::from_argv(&command_argv, wire_format)?0 ; |
1718 | 2 | let request = WorkRequest { |
1719 | 2 | arguments: persistent_worker_request_arguments(&command_argv), |
1720 | 2 | inputs: Vec::<PersistentWorkerInput>::new(), |
1721 | | request_id: 0, |
1722 | | cancel: false, |
1723 | | verbosity: 0, |
1724 | 2 | sandbox_dir: if command_proto.working_directory.is_empty() { |
1725 | 2 | self.work_directory.clone() |
1726 | | } else { |
1727 | 0 | format!( |
1728 | | "{}/{}", |
1729 | 0 | self.work_directory, command_proto.working_directory |
1730 | | ) |
1731 | | }, |
1732 | | }; |
1733 | 2 | let worker_cwd = |
1734 | 2 | PathBuf::from(&self.running_actions_manager.root_action_directory); |
1735 | | |
1736 | 2 | match self |
1737 | 2 | .running_actions_manager |
1738 | 2 | .persistent_worker_pool |
1739 | 2 | .acquire(key.clone(), &program, &worker_cwd) |
1740 | 2 | .await |
1741 | | { |
1742 | 2 | Ok(mut lease) => { |
1743 | 2 | let timer = self.metrics().child_process.begin_timer(); |
1744 | 2 | let dispatch_result = { |
1745 | 2 | let dispatch_fut = |
1746 | 2 | lease.worker().dispatch_with_timeout(&request, self.timeout); |
1747 | 2 | tokio::pin!(dispatch_fut); |
1748 | 2 | tokio::select! { |
1749 | 2 | result = &mut dispatch_fut => Some(result), |
1750 | 2 | _ = &mut kill_channel_rx => None0 , |
1751 | | } |
1752 | | }; |
1753 | 2 | let response = match dispatch_result { |
1754 | 2 | Some(Ok(response)) => { |
1755 | 2 | lease.release(true).await; |
1756 | 2 | response |
1757 | | } |
1758 | 0 | Some(Err(err)) => { |
1759 | 0 | lease.release(false).await; |
1760 | 0 | return Err(err).err_tip(|| { |
1761 | 0 | format!("Dispatching action to persistent worker {key:?}") |
1762 | 0 | }); |
1763 | | } |
1764 | | None => { |
1765 | 0 | drop(timer); |
1766 | 0 | lease.release(false).await; |
1767 | 0 | { |
1768 | 0 | let mut state = self.state.lock(); |
1769 | 0 | state.error = Error::merge_option( |
1770 | 0 | state.error.take(), |
1771 | 0 | Some(Error::new( |
1772 | 0 | Code::Cancelled, |
1773 | 0 | format!( |
1774 | 0 | "Persistent worker command '{}' was killed by scheduler", |
1775 | 0 | args.join(OsStr::new(" ")).to_string_lossy() |
1776 | 0 | ), |
1777 | 0 | )), |
1778 | 0 | ); |
1779 | 0 | state.command_proto = Some(command_proto); |
1780 | 0 | state.execution_result = |
1781 | 0 | Some(RunningActionImplExecutionResult { |
1782 | 0 | stdout: Bytes::new(), |
1783 | 0 | stderr: Bytes::new(), |
1784 | 0 | exit_code: EXIT_CODE_FOR_SIGNAL, |
1785 | 0 | resource_usage: None, |
1786 | 0 | }); |
1787 | 0 | state.execution_metadata.execution_completed_timestamp = |
1788 | 0 | (self.running_actions_manager.callbacks.now_fn)(); |
1789 | 0 | } |
1790 | 0 | return Ok(self); |
1791 | | } |
1792 | | }; |
1793 | 2 | timer.measure(); |
1794 | | |
1795 | 2 | if response.exit_code == 0 { |
1796 | 2 | self.metrics().child_process_success_error_code.inc(); |
1797 | 2 | } else { |
1798 | 0 | self.metrics().child_process_failure_error_code.inc(); |
1799 | 0 | } |
1800 | 2 | info!(?args, ?key, "Persistent worker command complete"); |
1801 | 2 | { |
1802 | 2 | let mut state = self.state.lock(); |
1803 | 2 | state.command_proto = Some(command_proto); |
1804 | 2 | state.execution_result = Some(RunningActionImplExecutionResult { |
1805 | 2 | stdout: Bytes::new(), |
1806 | 2 | stderr: Bytes::from(response.output), |
1807 | 2 | exit_code: response.exit_code, |
1808 | 2 | resource_usage: None, |
1809 | 2 | }); |
1810 | 2 | state.execution_metadata.execution_completed_timestamp = |
1811 | 2 | (self.running_actions_manager.callbacks.now_fn)(); |
1812 | 2 | } |
1813 | 2 | return Ok(self); |
1814 | | } |
1815 | 0 | Err(err) => { |
1816 | 0 | info!( |
1817 | | ?err, |
1818 | | ?key, |
1819 | | "Falling back to one-shot execution; persistent worker unavailable" |
1820 | | ); |
1821 | | } |
1822 | | } |
1823 | | } |
1824 | 0 | Err(err) => { |
1825 | 0 | info!( |
1826 | | ?err, |
1827 | | "Falling back to one-shot execution; unsupported persistent worker protocol" |
1828 | | ); |
1829 | | } |
1830 | | } |
1831 | 18 | } |
1832 | | |
1833 | 18 | let mut command_builder = process::Command::new(program); |
1834 | | #[cfg(target_family = "unix")] |
1835 | 18 | command_builder.arg0(args[0]); |
1836 | 18 | command_builder |
1837 | 18 | .args(&args[1..]) |
1838 | 18 | .kill_on_drop(true) |
1839 | 18 | .stdin(Stdio::null()) |
1840 | 18 | .stdout(Stdio::piped()) |
1841 | 18 | .stderr(Stdio::piped()) |
1842 | 18 | .current_dir(format!( |
1843 | 18 | "{}/{}", |
1844 | 18 | self.work_directory, command_proto.working_directory |
1845 | 18 | )) |
1846 | 18 | .env_clear(); |
1847 | | |
1848 | 18 | let requested_timeout = if self.action_info.timeout.is_zero() { |
1849 | 16 | self.running_actions_manager.max_action_timeout |
1850 | | } else { |
1851 | 2 | self.action_info.timeout |
1852 | | }; |
1853 | | |
1854 | 18 | let mut maybe_side_channel_file: Option<Cow<'_, OsStr>> = None; |
1855 | 18 | if let Some(additional_environment0 ) = &self |
1856 | 18 | .running_actions_manager |
1857 | 18 | .execution_configuration |
1858 | 18 | .additional_environment |
1859 | | { |
1860 | 0 | for (name, source) in additional_environment { |
1861 | 0 | let value = match source { |
1862 | 0 | EnvironmentSource::Property(property) => self |
1863 | 0 | .action_info |
1864 | 0 | .platform_properties |
1865 | 0 | .get(property) |
1866 | 0 | .map_or_else(|| Cow::Borrowed(""), |v| Cow::Borrowed(v.as_str())), |
1867 | 0 | EnvironmentSource::Value(value) => Cow::Borrowed(value.as_str()), |
1868 | | EnvironmentSource::FromEnvironment => { |
1869 | 0 | Cow::Owned(env::var(name).unwrap_or_default()) |
1870 | | } |
1871 | | EnvironmentSource::TimeoutMillis => { |
1872 | 0 | Cow::Owned(requested_timeout.as_millis().to_string()) |
1873 | | } |
1874 | | EnvironmentSource::SideChannelFile => { |
1875 | 0 | let file_cow = |
1876 | 0 | format!("{}/{}", self.action_directory, Uuid::new_v4().simple()); |
1877 | 0 | maybe_side_channel_file = Some(Cow::Owned(file_cow.clone().into())); |
1878 | 0 | Cow::Owned(file_cow) |
1879 | | } |
1880 | | EnvironmentSource::ActionDirectory => { |
1881 | 0 | Cow::Borrowed(self.action_directory.as_str()) |
1882 | | } |
1883 | | }; |
1884 | 0 | command_builder.env(name, value.as_ref()); |
1885 | | } |
1886 | 18 | } |
1887 | | |
1888 | | #[cfg(target_family = "unix")] |
1889 | 18 | let envs = &command_proto.environment_variables; |
1890 | | // If SystemRoot is not set on windows we set it to default. Failing to do |
1891 | | // this causes all commands to fail. |
1892 | | #[cfg(target_family = "windows")] |
1893 | | let envs = { |
1894 | | let mut envs = command_proto.environment_variables.clone(); |
1895 | | if !envs.iter().any(|v| v.name.to_uppercase() == "SYSTEMROOT") { |
1896 | | envs.push( |
1897 | | nativelink_proto::build::bazel::remote::execution::v2::command::EnvironmentVariable { |
1898 | | name: "SystemRoot".to_string(), |
1899 | | value: "C:\\Windows".to_string(), |
1900 | | }, |
1901 | | ); |
1902 | | } |
1903 | | if !envs.iter().any(|v| v.name.to_uppercase() == "PATH") { |
1904 | | envs.push( |
1905 | | nativelink_proto::build::bazel::remote::execution::v2::command::EnvironmentVariable { |
1906 | | name: "PATH".to_string(), |
1907 | | value: "C:\\Windows\\System32".to_string(), |
1908 | | }, |
1909 | | ); |
1910 | | } |
1911 | | envs |
1912 | | }; |
1913 | 18 | for environment_variable in envs { |
1914 | 18 | command_builder.env(&environment_variable.name, &environment_variable.value); |
1915 | 18 | } |
1916 | | |
1917 | | // Sandboxing of the command if we are running on Linux, this resolves issues where |
1918 | | // children can spawn children and also provides better reproducibility. |
1919 | | #[cfg(target_os = "linux")] |
1920 | | { |
1921 | 18 | let use_namespaces = self.running_actions_manager.use_namespaces; |
1922 | | |
1923 | 18 | if !matches!17 (use_namespaces, UseNamespaces::No) { |
1924 | 17 | let root_action_directory = std::ffi::CString::new( |
1925 | 17 | self.running_actions_manager.root_action_directory.clone(), |
1926 | | ) |
1927 | 17 | .err_tip(|| "In RunningActionImpl::inner_execute()")?0 ; |
1928 | 17 | let action_directory = std::ffi::CString::new(self.action_directory.clone()) |
1929 | 17 | .err_tip(|| "In RunningActionImpl::inner_execute()")?0 ; |
1930 | | |
1931 | | // SAFETY: This function is specifically designed to operate in a async-signal-safe |
1932 | | // environment. |
1933 | | unsafe { |
1934 | 17 | command_builder.pre_exec(move || {0 |
1935 | 0 | crate::namespace_utils::configure_namespace( |
1936 | 0 | matches!(use_namespaces, UseNamespaces::YesAndMount), |
1937 | 0 | &root_action_directory, |
1938 | 0 | &action_directory, |
1939 | | ) |
1940 | 0 | }); |
1941 | | } |
1942 | 1 | } |
1943 | | |
1944 | | // Run the action as its own process-group leader (pgid == child |
1945 | | // pid). The resource-usage sampler attributes memory by process |
1946 | | // group, so this keeps the whole action together — including |
1947 | | // processes reparented to the worker when an intermediate shell |
1948 | | // exits — and never conflates it with the worker's own group. |
1949 | 18 | command_builder.process_group(0); |
1950 | | } |
1951 | | |
1952 | 18 | let mut child_process = command_builder |
1953 | 18 | .spawn() |
1954 | 18 | .err_tip(|| format!0 ("Could not execute command {args:?}"))?0 ; |
1955 | 18 | let mut stdout_reader = child_process |
1956 | 18 | .stdout |
1957 | 18 | .take() |
1958 | 18 | .err_tip(|| "Expected stdout to exist on command this should never happen")?0 ; |
1959 | 18 | let mut stderr_reader = child_process |
1960 | 18 | .stderr |
1961 | 18 | .take() |
1962 | 18 | .err_tip(|| "Expected stderr to exist on command this should never happen")?0 ; |
1963 | | |
1964 | | #[cfg(target_os = "linux")] |
1965 | | // Wrap the child process to send SIGTERM rather than SIGKILL if namespaced to |
1966 | | // prevent zombie processes. |
1967 | 18 | let child_process = crate::namespace_utils::MaybeNamespacedChild::new( |
1968 | 17 | !matches!( |
1969 | 18 | self.running_actions_manager.use_namespaces, |
1970 | | UseNamespaces::No, |
1971 | | ), |
1972 | 18 | child_process, |
1973 | | ); |
1974 | | |
1975 | | #[cfg(target_os = "linux")] |
1976 | 18 | let mut maybe_resource_usage_sampler = |
1977 | 18 | child_process.id().map(start_action_resource_usage_sampler); |
1978 | | |
1979 | 18 | let mut child_process_guard = guard(child_process, |mut child_process| {0 |
1980 | 0 | let result: Result<Option<std::process::ExitStatus>, std::io::Error> = |
1981 | 0 | child_process.try_wait(); |
1982 | 0 | match result { |
1983 | 0 | Ok(res) if res.is_some() => { |
1984 | 0 | // The child already exited, probably a timeout or kill operation |
1985 | 0 | } |
1986 | 0 | result => { |
1987 | 0 | error!( |
1988 | | ?result, |
1989 | | "Child process was not cleaned up before dropping the call to execute(), killing in background spawn." |
1990 | | ); |
1991 | 0 | background_spawn!("running_actions_manager_kill_child_process", async move { |
1992 | 0 | drop(child_process.kill().await); |
1993 | 0 | }); |
1994 | | } |
1995 | | } |
1996 | 0 | }); |
1997 | | |
1998 | 18 | let all_stdout_fut = spawn!("stdout_reader", async move { |
1999 | 18 | let mut all_stdout = BytesMut::new(); |
2000 | | loop { |
2001 | 23 | let sz = stdout_reader |
2002 | 23 | .read_buf(&mut all_stdout) |
2003 | 23 | .await |
2004 | 23 | .err_tip(|| "Error reading stdout stream")?0 ; |
2005 | 23 | if sz == 0 { |
2006 | 18 | break; // EOF. |
2007 | 5 | } |
2008 | | } |
2009 | 18 | Result::<Bytes, Error>::Ok(all_stdout.freeze()) |
2010 | 18 | }); |
2011 | 18 | let all_stderr_fut = spawn!("stderr_reader", async move { |
2012 | 18 | let mut all_stderr = BytesMut::new(); |
2013 | | loop { |
2014 | 22 | let sz = stderr_reader |
2015 | 22 | .read_buf(&mut all_stderr) |
2016 | 22 | .await |
2017 | 22 | .err_tip(|| "Error reading stderr stream")?0 ; |
2018 | 22 | if sz == 0 { |
2019 | 18 | break; // EOF. |
2020 | 4 | } |
2021 | | } |
2022 | 18 | Result::<Bytes, Error>::Ok(all_stderr.freeze()) |
2023 | 18 | }); |
2024 | 18 | let mut killed_action = false; |
2025 | | |
2026 | 18 | let timer = self.metrics().child_process.begin_timer(); |
2027 | 18 | let mut sleep_fut = (self.running_actions_manager.callbacks.sleep_fn)(self.timeout).fuse(); |
2028 | | loop { |
2029 | 22 | tokio::select! { |
2030 | 22 | () = &mut sleep_fut => { |
2031 | 2 | self.running_actions_manager.metrics.task_timeouts.inc(); |
2032 | 2 | killed_action = true; |
2033 | 2 | if let Err(err0 ) = child_process_guard.kill().await { |
2034 | 0 | error!( |
2035 | | ?err, |
2036 | | "Could not kill process in RunningActionsManager for action timeout", |
2037 | | ); |
2038 | 2 | } |
2039 | | { |
2040 | 2 | let joined_command = args.join(OsStr::new(" ")); |
2041 | 2 | let command = joined_command.to_string_lossy(); |
2042 | 2 | info!( |
2043 | 2 | seconds = self.action_info.timeout.as_secs_f32(), |
2044 | | %command, |
2045 | | "Command timed out" |
2046 | | ); |
2047 | 2 | let mut state = self.state.lock(); |
2048 | 2 | state.error = Error::merge_option(state.error.take(), Some(Error::new( |
2049 | 2 | Code::DeadlineExceeded, |
2050 | 2 | format!( |
2051 | 2 | "Command '{}' timed out after {} seconds", |
2052 | 2 | command, |
2053 | 2 | self.action_info.timeout.as_secs_f32() |
2054 | 2 | ) |
2055 | 2 | ))); |
2056 | | } |
2057 | | }, |
2058 | 22 | maybe_exit_status18 = child_process_guard.wait() => { |
2059 | | // Defuse our guard so it does not try to cleanup and make senseless logs. |
2060 | 18 | drop(ScopeGuard::<_, _>::into_inner(child_process_guard)); |
2061 | 18 | let exit_status = maybe_exit_status.err_tip(|| "Failed to collect exit code of process")?0 ; |
2062 | | // TODO(palfrey) We should implement stderr/stdout streaming to client here. |
2063 | | // If we get killed before the stream is started, then these will lock up. |
2064 | | // TODO(palfrey) There is a significant bug here. If we kill the action and the action creates |
2065 | | // child processes, it can create zombies. See: https://github.com/tracemachina/nativelink/issues/225 |
2066 | 18 | let (stdout, stderr) = if killed_action { |
2067 | 4 | drop(timer); |
2068 | 4 | (Bytes::new(), Bytes::new()) |
2069 | | } else { |
2070 | 14 | timer.measure(); |
2071 | 14 | let (maybe_all_stdout, maybe_all_stderr) = tokio::join!(all_stdout_fut, all_stderr_fut); |
2072 | | ( |
2073 | 14 | maybe_all_stdout.err_tip(|| "Internal error reading from stdout of worker task")?0 ?0 , |
2074 | 14 | maybe_all_stderr.err_tip(|| "Internal error reading from stderr of worker task")?0 ?0 |
2075 | | ) |
2076 | | }; |
2077 | | |
2078 | 18 | let exit_code = exit_status.code().map_or_else(|| {4 |
2079 | | // No exit code means the runner was terminated by a |
2080 | | // signal. SIGKILL on Linux is the kernel OOM killer's |
2081 | | // weapon of choice, so flag this for operators trying |
2082 | | // to correlate action failures with kubectl-top |
2083 | | // memory pressure. |
2084 | 4 | warn!( |
2085 | | ?args, |
2086 | | "Runner subprocess terminated by signal (no exit code); likely OOMKilled \ |
2087 | | or externally killed. If this repeats for the same action, raise \ |
2088 | | `workers.specs[*].resources.limits.memory` or shrink the action's \ |
2089 | | concurrency." |
2090 | | ); |
2091 | 4 | self.metrics().child_process_failure_error_code.inc(); |
2092 | 4 | EXIT_CODE_FOR_SIGNAL |
2093 | 14 | }4 , |exit_code| { |
2094 | 14 | if exit_code == 0 { |
2095 | 13 | self.metrics().child_process_success_error_code.inc(); |
2096 | 13 | } else { |
2097 | 1 | self.metrics().child_process_failure_error_code.inc(); |
2098 | 1 | } |
2099 | 14 | exit_code |
2100 | 14 | }); |
2101 | | |
2102 | | #[cfg(target_os = "linux")] |
2103 | 18 | let resource_usage = match maybe_resource_usage_sampler.take() { |
2104 | 18 | Some(sampler) => finish_action_resource_usage_sampler(sampler) |
2105 | 18 | .await |
2106 | 18 | .and_then(|usage| { |
2107 | | // An action too short to catch a sample leaves |
2108 | | // both at zero; report nothing rather than a |
2109 | | // misleading zero. |
2110 | 18 | (usage.peak_memory_kb > 0 || usage.cpu_time_ms > 02 ).then_some( |
2111 | 18 | ActionResourceUsage { |
2112 | 18 | peak_memory_kb: usage.peak_memory_kb, |
2113 | 18 | cpu_time_ms: usage.cpu_time_ms, |
2114 | 18 | sampled: true, |
2115 | 18 | operation_id: String::new(), |
2116 | 18 | worker_id: String::new(), |
2117 | 18 | }, |
2118 | | ) |
2119 | 18 | }), |
2120 | 0 | None => None, |
2121 | | }; |
2122 | | #[cfg(not(target_os = "linux"))] |
2123 | | let resource_usage = None; |
2124 | | |
2125 | | // log something useful instead of repeating same ?arg |
2126 | 18 | info!(?exit_code, "Command complete"); |
2127 | | |
2128 | 18 | let maybe_error_override = if let Some(side_channel_file0 ) = maybe_side_channel_file { |
2129 | 0 | process_side_channel_file(side_channel_file.clone(), &args, requested_timeout).await |
2130 | 0 | .err_tip(|| format!("Error processing side channel file: {}", side_channel_file.display()))? |
2131 | | } else { |
2132 | 18 | None |
2133 | | }; |
2134 | 18 | { |
2135 | 18 | let mut state = self.state.lock(); |
2136 | 18 | state.error = Error::merge_option(state.error.take(), maybe_error_override); |
2137 | 18 | |
2138 | 18 | state.command_proto = Some(command_proto); |
2139 | 18 | state.execution_result = Some(RunningActionImplExecutionResult{ |
2140 | 18 | stdout, |
2141 | 18 | stderr, |
2142 | 18 | exit_code, |
2143 | 18 | resource_usage, |
2144 | 18 | }); |
2145 | 18 | state.execution_metadata.execution_completed_timestamp = (self.running_actions_manager.callbacks.now_fn)(); |
2146 | 18 | } |
2147 | 18 | return Ok(self); |
2148 | | }, |
2149 | 22 | _ = &mut kill_channel_rx => { |
2150 | 2 | killed_action = true; |
2151 | 2 | if let Err(err0 ) = child_process_guard.kill().await { |
2152 | 0 | error!( |
2153 | 0 | operation_id = ?self.operation_id, |
2154 | | ?err, |
2155 | | "Could not kill process", |
2156 | | ); |
2157 | 2 | } |
2158 | 2 | { |
2159 | 2 | let mut state = self.state.lock(); |
2160 | 2 | state.error = Error::merge_option(state.error.take(), Some(Error::new( |
2161 | 2 | Code::Aborted, |
2162 | 2 | format!( |
2163 | 2 | "Command '{}' was killed by scheduler", |
2164 | 2 | args.join(OsStr::new(" ")).to_string_lossy() |
2165 | 2 | ) |
2166 | 2 | ))); |
2167 | 2 | } |
2168 | | }, |
2169 | | } |
2170 | | } |
2171 | | // Unreachable. |
2172 | 21 | } |
2173 | | |
2174 | 18 | async fn inner_upload_results(self: Arc<Self>) -> Result<Arc<Self>, Error>0 { |
2175 | | enum OutputType { |
2176 | | None, |
2177 | | File(FileInfo), |
2178 | | Directory(DirectoryInfo), |
2179 | | FileSymlink(SymlinkInfo), |
2180 | | DirectorySymlink(SymlinkInfo), |
2181 | | } |
2182 | | |
2183 | 18 | let upload_start = std::time::Instant::now(); |
2184 | 18 | debug!( |
2185 | 18 | operation_id = ?self.operation_id, |
2186 | | "Worker uploading results - starting", |
2187 | | ); |
2188 | 18 | let (mut command_proto, execution_result, mut execution_metadata) = { |
2189 | 18 | let mut state = self.state.lock(); |
2190 | 18 | state.execution_metadata.output_upload_start_timestamp = |
2191 | 18 | (self.running_actions_manager.callbacks.now_fn)(); |
2192 | | ( |
2193 | 18 | state |
2194 | 18 | .command_proto |
2195 | 18 | .take() |
2196 | 18 | .err_tip(|| "Expected state to have command_proto in execute()")?0 , |
2197 | 18 | state |
2198 | 18 | .execution_result |
2199 | 18 | .take() |
2200 | 18 | .err_tip(|| "Execution result does not exist at upload_results stage")?0 , |
2201 | 18 | state.execution_metadata.clone(), |
2202 | | ) |
2203 | | }; |
2204 | 18 | let cas_store = self.running_actions_manager.cas_store.as_ref(); |
2205 | 18 | let hasher = self.action_info.unique_qualifier.digest_function(); |
2206 | | |
2207 | 18 | let mut output_path_futures = FuturesUnordered::new(); |
2208 | 18 | let mut output_paths = command_proto.output_paths; |
2209 | 18 | if output_paths.is_empty() { |
2210 | 7 | output_paths |
2211 | 7 | .reserve(command_proto.output_files.len() + command_proto.output_directories.len()); |
2212 | 7 | output_paths.append(&mut command_proto.output_files); |
2213 | 7 | output_paths.append(&mut command_proto.output_directories); |
2214 | 11 | } |
2215 | 18 | let digest_uploaders = Arc::new(Mutex::new(HashMap::new())); |
2216 | 18 | for entry14 in output_paths { |
2217 | 14 | let full_path = OsString::from(if command_proto.working_directory.is_empty() { |
2218 | 3 | format!("{}/{}", self.work_directory, entry) |
2219 | | } else { |
2220 | 11 | format!( |
2221 | | "{}/{}/{}", |
2222 | 11 | self.work_directory, command_proto.working_directory, entry |
2223 | | ) |
2224 | | }); |
2225 | 14 | let work_directory = &self.work_directory; |
2226 | 14 | let digest_uploaders = digest_uploaders.clone(); |
2227 | 14 | output_path_futures.push(async move { |
2228 | 7 | let metadata = { |
2229 | 14 | let metadata = match fs::symlink_metadata(&full_path).await { |
2230 | 14 | Ok(file) => file, |
2231 | 0 | Err(e) => { |
2232 | 0 | if e.code == Code::NotFound { |
2233 | | // In the event our output does not exist, according to the bazel remote |
2234 | | // execution spec, we simply ignore it continue. |
2235 | 0 | return Result::<OutputType, Error>::Ok(OutputType::None); |
2236 | 0 | } |
2237 | 0 | return Err(e).err_tip(|| { |
2238 | 0 | format!("Could not open file {}", full_path.display()) |
2239 | 0 | }); |
2240 | | } |
2241 | | }; |
2242 | | |
2243 | 14 | if metadata.is_file() { |
2244 | | return Ok(OutputType::File( |
2245 | 7 | upload_file( |
2246 | 7 | cas_store.as_pin(), |
2247 | 7 | &full_path, |
2248 | 7 | hasher, |
2249 | 7 | metadata, |
2250 | 7 | digest_uploaders, |
2251 | 7 | ) |
2252 | 7 | .await |
2253 | 7 | .map(|mut file_info| { |
2254 | 7 | file_info.name_or_path = NameOrPath::Path(entry); |
2255 | 7 | file_info |
2256 | 7 | }) |
2257 | 7 | .err_tip(|| format!0 ("Uploading file {}", full_path.display()0 ))?0 , |
2258 | | )); |
2259 | 7 | } |
2260 | 7 | metadata |
2261 | | }; |
2262 | 7 | if metadata.is_dir() { |
2263 | | Ok(OutputType::Directory( |
2264 | 3 | upload_directory( |
2265 | 3 | cas_store.as_pin(), |
2266 | 3 | &full_path, |
2267 | 3 | work_directory, |
2268 | 3 | hasher, |
2269 | 3 | digest_uploaders, |
2270 | | ) |
2271 | 3 | .and_then(|(root_dir, children)| async move { |
2272 | 3 | let tree = ProtoTree { |
2273 | 3 | root: Some(root_dir), |
2274 | 3 | children: children.into(), |
2275 | 3 | }; |
2276 | 3 | let tree_digest = serialize_and_upload_message( |
2277 | 3 | &tree, |
2278 | 3 | cas_store.as_pin(), |
2279 | 3 | &mut hasher.hasher(), |
2280 | 3 | ) |
2281 | 3 | .await |
2282 | 3 | .err_tip(|| format!0 ("While processing {entry}"))?0 ; |
2283 | 3 | Ok(DirectoryInfo { |
2284 | 3 | path: entry, |
2285 | 3 | tree_digest, |
2286 | 3 | }) |
2287 | 6 | }) |
2288 | 3 | .await |
2289 | 3 | .err_tip(|| format!0 ("Uploading directory {}", full_path.display()0 ))?0 , |
2290 | | )) |
2291 | 4 | } else if metadata.is_symlink() { |
2292 | | // Resolve the symlink to determine what it points to. |
2293 | | // Symlinks created by DirectoryCache (absolute paths into |
2294 | | // the cache directory) must NOT be uploaded as symlinks — |
2295 | | // the target path is worker-local and meaningless to the |
2296 | | // client. Instead, follow the symlink and upload the |
2297 | | // resolved content (file or directory). |
2298 | 4 | let target = fs::read_link(&full_path).await.err_tip(|| {0 |
2299 | 0 | format!("Reading symlink target for {}", full_path.display()) |
2300 | 0 | })?; |
2301 | 4 | let is_absolute_symlink = Path::new(&target).is_absolute(); |
2302 | | |
2303 | 4 | if is_absolute_symlink { |
2304 | | // Absolute symlink — resolve and upload contents. |
2305 | 3 | match fs::metadata(&full_path).await { |
2306 | 3 | Ok(resolved_meta) => { |
2307 | 3 | if resolved_meta.is_dir() { |
2308 | | // Upload as directory (Tree proto). |
2309 | | Ok(OutputType::Directory( |
2310 | 1 | upload_directory( |
2311 | 1 | cas_store.as_pin(), |
2312 | 1 | &full_path, |
2313 | 1 | work_directory, |
2314 | 1 | hasher, |
2315 | 1 | digest_uploaders, |
2316 | | ) |
2317 | 1 | .and_then(|(root_dir, children)| async move { |
2318 | 1 | let tree = ProtoTree { |
2319 | 1 | root: Some(root_dir), |
2320 | 1 | children: children.into(), |
2321 | 1 | }; |
2322 | 1 | let tree_digest = serialize_and_upload_message( |
2323 | 1 | &tree, |
2324 | 1 | cas_store.as_pin(), |
2325 | 1 | &mut hasher.hasher(), |
2326 | 1 | ) |
2327 | 1 | .await |
2328 | 1 | .err_tip(|| format!0 ("While processing {entry}"))?0 ; |
2329 | 1 | Ok(DirectoryInfo { |
2330 | 1 | path: entry, |
2331 | 1 | tree_digest, |
2332 | 1 | }) |
2333 | 2 | }) |
2334 | 1 | .await |
2335 | 1 | .err_tip(|| {0 |
2336 | 0 | format!( |
2337 | | "Uploading symlinked directory {}", |
2338 | 0 | full_path.display() |
2339 | | ) |
2340 | 0 | })?, |
2341 | | )) |
2342 | | } else { |
2343 | | // Upload as file (follow symlink). |
2344 | | Ok(OutputType::File( |
2345 | 2 | upload_file( |
2346 | 2 | cas_store.as_pin(), |
2347 | 2 | &full_path, |
2348 | 2 | hasher, |
2349 | 2 | resolved_meta, |
2350 | 2 | digest_uploaders, |
2351 | 2 | ) |
2352 | 2 | .await |
2353 | 2 | .map(|mut file_info| { |
2354 | 2 | file_info.name_or_path = NameOrPath::Path(entry); |
2355 | 2 | file_info |
2356 | 2 | }) |
2357 | 2 | .err_tip(|| {0 |
2358 | 0 | format!( |
2359 | | "Uploading symlinked file {}", |
2360 | 0 | full_path.display() |
2361 | | ) |
2362 | 0 | })?, |
2363 | | )) |
2364 | | } |
2365 | | } |
2366 | 0 | Err(e) => { |
2367 | 0 | if e.code != Code::NotFound { |
2368 | 0 | return Err(e).err_tip(|| { |
2369 | 0 | format!( |
2370 | | "While resolving absolute symlink {}", |
2371 | 0 | full_path.display() |
2372 | | ) |
2373 | 0 | }); |
2374 | 0 | } |
2375 | 0 | Ok(OutputType::None) |
2376 | | } |
2377 | | } |
2378 | | } else { |
2379 | | // Relative symlink — action intentionally created it. |
2380 | | // Upload as a proper symlink. |
2381 | 1 | let output_symlink = upload_symlink(&full_path, work_directory) |
2382 | 1 | .await |
2383 | 1 | .map(|mut symlink_info| { |
2384 | 1 | symlink_info.name_or_path = NameOrPath::Path(entry); |
2385 | 1 | symlink_info |
2386 | 1 | }) |
2387 | 1 | .err_tip(|| format!0 ("Uploading symlink {}", full_path.display()0 ))?0 ; |
2388 | 1 | match fs::metadata(&full_path).await { |
2389 | 1 | Ok(metadata) => { |
2390 | 1 | if metadata.is_dir() { |
2391 | 0 | Ok(OutputType::DirectorySymlink(output_symlink)) |
2392 | | } else { |
2393 | | // Note: If it's anything but directory we put it as a file symlink. |
2394 | 1 | Ok(OutputType::FileSymlink(output_symlink)) |
2395 | | } |
2396 | | } |
2397 | 0 | Err(e) => { |
2398 | 0 | if e.code != Code::NotFound { |
2399 | 0 | return Err(e).err_tip(|| { |
2400 | 0 | format!( |
2401 | | "While querying target symlink metadata for {}", |
2402 | 0 | full_path.display() |
2403 | | ) |
2404 | 0 | }); |
2405 | 0 | } |
2406 | | // If the file doesn't exist, we consider it a file. Even though the |
2407 | | // file doesn't exist we still need to populate an entry. |
2408 | 0 | Ok(OutputType::FileSymlink(output_symlink)) |
2409 | | } |
2410 | | } |
2411 | | } |
2412 | | } else { |
2413 | 0 | Err(make_err!( |
2414 | 0 | Code::Internal, |
2415 | 0 | "{full_path:?} was not a file, folder or symlink. Must be one.", |
2416 | 0 | )) |
2417 | | } |
2418 | 14 | }); |
2419 | | } |
2420 | 18 | let mut output_files = vec![]; |
2421 | 18 | let mut output_folders = vec![]; |
2422 | 18 | let mut output_directory_symlinks = vec![]; |
2423 | 18 | let mut output_file_symlinks = vec![]; |
2424 | | |
2425 | 18 | if execution_result.exit_code != 0 { |
2426 | 5 | let stdout = core::str::from_utf8(&execution_result.stdout).unwrap_or("<no-utf8>"); |
2427 | 5 | let stderr = core::str::from_utf8(&execution_result.stderr).unwrap_or("<no-utf8>"); |
2428 | 5 | error!( |
2429 | | exit_code = ?execution_result.exit_code, |
2430 | 5 | stdout = ?stdout[..min(stdout.len(), 1000)], |
2431 | 5 | stderr = ?stderr[..min(stderr.len(), 1000)], |
2432 | | command = ?command_proto.arguments, |
2433 | | "Command returned non-zero exit code", |
2434 | | ); |
2435 | 13 | } |
2436 | | |
2437 | 18 | let stdout_digest_fut = self.metrics().upload_stdout.wrap(async { |
2438 | 18 | let start = std::time::Instant::now(); |
2439 | 18 | let data = execution_result.stdout; |
2440 | 18 | let data_len = data.len(); |
2441 | 18 | let digest = compute_buf_digest(&data, &mut hasher.hasher()); |
2442 | 18 | cas_store |
2443 | 18 | .update_oneshot(digest, data) |
2444 | 18 | .await |
2445 | 18 | .err_tip(|| "Uploading stdout")?0 ; |
2446 | 18 | debug!( |
2447 | | ?digest, |
2448 | | data_len, |
2449 | 18 | elapsed_ms = start.elapsed().as_millis(), |
2450 | | "upload_results: stdout upload completed", |
2451 | | ); |
2452 | 18 | Result::<DigestInfo, Error>::Ok(digest) |
2453 | 18 | }); |
2454 | 18 | let stderr_digest_fut = self.metrics().upload_stderr.wrap(async { |
2455 | 18 | let start = std::time::Instant::now(); |
2456 | 18 | let data = execution_result.stderr; |
2457 | 18 | let data_len = data.len(); |
2458 | 18 | let digest = compute_buf_digest(&data, &mut hasher.hasher()); |
2459 | 18 | cas_store |
2460 | 18 | .update_oneshot(digest, data) |
2461 | 18 | .await |
2462 | 18 | .err_tip(|| "Uploading stderr")?0 ; |
2463 | 18 | debug!( |
2464 | | ?digest, |
2465 | | data_len, |
2466 | 18 | elapsed_ms = start.elapsed().as_millis(), |
2467 | | "upload_results: stderr upload completed", |
2468 | | ); |
2469 | 18 | Result::<DigestInfo, Error>::Ok(digest) |
2470 | 18 | }); |
2471 | | |
2472 | 18 | debug!( |
2473 | 18 | operation_id = ?self.operation_id, |
2474 | 18 | num_output_paths = output_path_futures.len(), |
2475 | | "upload_results: starting stdout/stderr/output_paths uploads", |
2476 | | ); |
2477 | 18 | let join_start = std::time::Instant::now(); |
2478 | 18 | let upload_result = futures::try_join!(stdout_digest_fut, stderr_digest_fut, async { |
2479 | 32 | while let Some(output_type14 ) = output_path_futures.try_next().await?0 { |
2480 | 14 | match output_type { |
2481 | 9 | OutputType::File(output_file) => output_files.push(output_file), |
2482 | 4 | OutputType::Directory(output_folder) => output_folders.push(output_folder), |
2483 | 1 | OutputType::FileSymlink(output_symlink) => { |
2484 | 1 | output_file_symlinks.push(output_symlink); |
2485 | 1 | } |
2486 | 0 | OutputType::DirectorySymlink(output_symlink) => { |
2487 | 0 | output_directory_symlinks.push(output_symlink); |
2488 | 0 | } |
2489 | 0 | OutputType::None => { /* Safe to ignore */ } |
2490 | | } |
2491 | | } |
2492 | 18 | Ok(()) |
2493 | 18 | }); |
2494 | 18 | drop(output_path_futures); |
2495 | 18 | debug!( |
2496 | 18 | operation_id = ?self.operation_id, |
2497 | 18 | elapsed_ms = join_start.elapsed().as_millis(), |
2498 | 18 | success = upload_result.is_ok(), |
2499 | | "upload_results: all uploads completed", |
2500 | | ); |
2501 | 18 | let resource_usage = execution_result.resource_usage.clone(); |
2502 | 18 | let (stdout_digest, stderr_digest) = match upload_result { |
2503 | 18 | Ok((stdout_digest, stderr_digest, ())) => (stdout_digest, stderr_digest), |
2504 | 0 | Err(e) => return Err(e).err_tip(|| "Error while uploading results"), |
2505 | | }; |
2506 | | |
2507 | 18 | execution_metadata.output_upload_completed_timestamp = |
2508 | 18 | (self.running_actions_manager.callbacks.now_fn)(); |
2509 | 18 | output_files.sort_unstable_by(|a, b| a.name_or_path0 .cmp0 (&b.name_or_path0 )); |
2510 | 18 | output_folders.sort_unstable_by(|a, b| a.path0 .cmp0 (&b.path0 )); |
2511 | 18 | output_file_symlinks.sort_unstable_by(|a, b| a.name_or_path0 .cmp0 (&b.name_or_path0 )); |
2512 | 18 | output_directory_symlinks.sort_unstable_by(|a, b| a.name_or_path0 .cmp0 (&b.name_or_path0 )); |
2513 | 18 | let num_output_files = output_files.len(); |
2514 | 18 | let num_output_folders = output_folders.len(); |
2515 | 18 | { |
2516 | 18 | let mut state = self.state.lock(); |
2517 | 18 | execution_metadata.worker_completed_timestamp = |
2518 | 18 | (self.running_actions_manager.callbacks.now_fn)(); |
2519 | 18 | state.action_result = Some(ActionResult { |
2520 | 18 | output_files, |
2521 | 18 | output_folders, |
2522 | 18 | output_directory_symlinks, |
2523 | 18 | output_file_symlinks, |
2524 | 18 | exit_code: execution_result.exit_code, |
2525 | 18 | stdout_digest, |
2526 | 18 | stderr_digest, |
2527 | 18 | execution_metadata, |
2528 | 18 | server_logs: HashMap::default(), // TODO(palfrey) Not implemented. |
2529 | 18 | error: state.error.clone(), |
2530 | 18 | message: String::new(), // Will be filled in on cache_action_result if needed. |
2531 | 18 | }); |
2532 | 18 | state.resource_usage = resource_usage; |
2533 | 18 | } |
2534 | 18 | debug!( |
2535 | 18 | operation_id = ?self.operation_id, |
2536 | 18 | total_elapsed_ms = upload_start.elapsed().as_millis(), |
2537 | | num_output_files, |
2538 | | num_output_folders, |
2539 | | "upload_results: inner_upload_results completed successfully", |
2540 | | ); |
2541 | 18 | Ok(self) |
2542 | 18 | } |
2543 | | |
2544 | 18 | async fn inner_get_finished_result(self: Arc<Self>) -> Result<ActionResult, Error> { |
2545 | 18 | let mut state = self.state.lock(); |
2546 | 18 | state |
2547 | 18 | .action_result |
2548 | 18 | .take() |
2549 | 18 | .err_tip(|| "Expected action_result to exist in get_finished_result") |
2550 | 18 | } |
2551 | | } |
2552 | | |
2553 | | impl Drop for RunningActionImpl { |
2554 | 229 | fn drop(&mut self) { |
2555 | 229 | if self.did_cleanup.load(Ordering::Acquire) { |
2556 | 228 | if self.has_manager_entry.load(Ordering::Acquire) { |
2557 | 2 | drop( |
2558 | 2 | self.running_actions_manager |
2559 | 2 | .cleanup_action(&self.operation_id), |
2560 | 2 | ); |
2561 | 226 | } |
2562 | 228 | if let Some(input_lease1 ) = self.input_lease.clone() { |
2563 | 1 | background_spawn!( |
2564 | | "running_action_impl_release_input_lease", |
2565 | 1 | input_lease.release() |
2566 | | ); |
2567 | 227 | } |
2568 | 228 | return; |
2569 | 1 | } |
2570 | 1 | let operation_id = self.operation_id.clone(); |
2571 | 1 | error!( |
2572 | | %operation_id, |
2573 | | "RunningActionImpl did not cleanup. This is a violation of the requirements, will attempt to do it in the background." |
2574 | | ); |
2575 | 1 | let running_actions_manager = self.running_actions_manager.clone(); |
2576 | 1 | let action_directory = self.action_directory.clone(); |
2577 | 1 | let input_lease = self.input_lease.clone(); |
2578 | 1 | background_spawn!("running_action_impl_drop", async move {0 |
2579 | 0 | let cleanup_result = |
2580 | 0 | do_cleanup(&running_actions_manager, &operation_id, &action_directory).await; |
2581 | 0 | if let Some(input_lease) = input_lease { |
2582 | 0 | input_lease.release().await; |
2583 | 0 | } |
2584 | 0 | if let Err(err) = cleanup_result { |
2585 | 0 | error!( |
2586 | | %operation_id, |
2587 | | ?action_directory, |
2588 | | ?err, |
2589 | | "Error cleaning up action" |
2590 | | ); |
2591 | 0 | } |
2592 | 0 | }); |
2593 | 229 | } |
2594 | | } |
2595 | | |
2596 | | impl RunningAction for RunningActionImpl { |
2597 | 0 | fn get_operation_id(&self) -> &OperationId { |
2598 | 0 | &self.operation_id |
2599 | 0 | } |
2600 | | |
2601 | 25 | async fn prepare_action(self: Arc<Self>) -> Result<Arc<Self>, Error> { |
2602 | 25 | let res = self |
2603 | 25 | .metrics() |
2604 | 25 | .clone() |
2605 | 25 | .prepare_action |
2606 | 25 | .wrap(Self::inner_prepare_action(self)) |
2607 | 25 | .await; |
2608 | 25 | if let Err(ref e0 ) = res { |
2609 | 0 | warn!(?e, "Error during prepare_action"); |
2610 | 25 | } |
2611 | 25 | res |
2612 | 25 | } |
2613 | | |
2614 | 21 | async fn execute(self: Arc<Self>) -> Result<Arc<Self>, Error> { |
2615 | 21 | let res = self |
2616 | 21 | .metrics() |
2617 | 21 | .clone() |
2618 | 21 | .execute |
2619 | 21 | .wrap(Self::inner_execute(self)) |
2620 | 21 | .await; |
2621 | 21 | if let Err(ref e1 ) = res { |
2622 | 1 | warn!(?e, "Error during prepare_action"); |
2623 | 20 | } |
2624 | 21 | res |
2625 | 21 | } |
2626 | | |
2627 | 18 | async fn upload_results(self: Arc<Self>) -> Result<Arc<Self>, Error>0 { |
2628 | 18 | let upload_timeout = self.running_actions_manager.max_upload_timeout; |
2629 | 18 | let operation_id = self.operation_id.clone(); |
2630 | 18 | info!( |
2631 | | ?operation_id, |
2632 | 18 | upload_timeout_s = upload_timeout.as_secs(), |
2633 | | "upload_results: starting with timeout", |
2634 | | ); |
2635 | 18 | let metrics = self.metrics().clone(); |
2636 | 18 | let upload_fut = metrics |
2637 | 18 | .upload_results |
2638 | 18 | .wrap(Self::inner_upload_results(self)); |
2639 | | |
2640 | 18 | let stall_warn_fut = async {16 |
2641 | 16 | let mut elapsed_secs = 0u64; |
2642 | | loop { |
2643 | 16 | tokio::time::sleep(Duration::from_mins(1)).await; |
2644 | 0 | elapsed_secs += 60; |
2645 | 0 | warn!( |
2646 | | ?operation_id, |
2647 | | elapsed_s = elapsed_secs, |
2648 | 0 | timeout_s = upload_timeout.as_secs(), |
2649 | | "upload_results: still in progress — possible stall", |
2650 | | ); |
2651 | | } |
2652 | | }; |
2653 | | |
2654 | 18 | let res = tokio::time::timeout(upload_timeout, async { |
2655 | 18 | tokio::pin!(upload_fut); |
2656 | 18 | tokio::pin!(stall_warn_fut); |
2657 | 18 | tokio::select! { |
2658 | 18 | result = &mut upload_fut => result, |
2659 | 18 | () = &mut stall_warn_fut => unreachable!0 (), |
2660 | | } |
2661 | 18 | }) |
2662 | 18 | .await |
2663 | 18 | .map_err(|err| {0 |
2664 | 0 | warn!(%operation_id, timeout=upload_timeout.as_secs(), "Upload results timeout"); |
2665 | 0 | Error::from_std_err(Code::DeadlineExceeded, &err).append(format!( |
2666 | | "Upload results timed out after {}s for operation {:?}", |
2667 | 0 | upload_timeout.as_secs(), |
2668 | | operation_id, |
2669 | | )) |
2670 | 0 | })?; |
2671 | 18 | if let Err(ref e0 ) = res { |
2672 | 0 | warn!(?operation_id, ?e, "Error during upload_results"); |
2673 | 18 | } |
2674 | 18 | res |
2675 | 18 | } |
2676 | | |
2677 | 226 | async fn cleanup(self: Arc<Self>) -> Result<Arc<Self>, Error> { |
2678 | 226 | let res = self |
2679 | 226 | .metrics() |
2680 | 226 | .clone() |
2681 | 226 | .cleanup |
2682 | 226 | .wrap(async move { |
2683 | 226 | let result = do_cleanup( |
2684 | 226 | &self.running_actions_manager, |
2685 | 226 | &self.operation_id, |
2686 | 226 | &self.action_directory, |
2687 | 226 | ) |
2688 | 226 | .await; |
2689 | 226 | self.has_manager_entry.store(false, Ordering::Release); |
2690 | 226 | self.did_cleanup.store(true, Ordering::Release); |
2691 | | // The work directory and manager entry are gone before the |
2692 | | // lease is released. If this future is cancelled while the |
2693 | | // release task is finishing, Drop still observes a completed |
2694 | | // cleanup and cannot strand the action in the manager. |
2695 | 226 | if let Some(input_lease1 ) = self.input_lease.clone() { |
2696 | 1 | input_lease.release().await; |
2697 | 225 | } |
2698 | 226 | result.map(move |()| self) |
2699 | 226 | }) |
2700 | 226 | .await; |
2701 | 226 | if let Err(ref e0 ) = res { |
2702 | 0 | warn!(?e, "Error during cleanup"); |
2703 | 226 | } |
2704 | 226 | res |
2705 | 226 | } |
2706 | | |
2707 | 18 | async fn get_finished_result(self: Arc<Self>) -> Result<ActionResult, Error>0 { |
2708 | 18 | self.metrics() |
2709 | 18 | .clone() |
2710 | 18 | .get_finished_result |
2711 | 18 | .wrap(Self::inner_get_finished_result(self)) |
2712 | 18 | .await |
2713 | 18 | } |
2714 | | |
2715 | 0 | fn resource_usage(&self) -> Option<ActionResourceUsage> { |
2716 | 0 | self.state.lock().resource_usage.clone() |
2717 | 0 | } |
2718 | | |
2719 | 0 | fn get_work_directory(&self) -> &String { |
2720 | 0 | &self.work_directory |
2721 | 0 | } |
2722 | | } |
2723 | | |
2724 | | pub trait RunningActionsManager: Sync + Send + Sized + Unpin + 'static { |
2725 | | type RunningAction: RunningAction; |
2726 | | |
2727 | | fn create_and_add_action( |
2728 | | self: &Arc<Self>, |
2729 | | worker_id: String, |
2730 | | start_execute: StartExecute, |
2731 | | ) -> impl Future<Output = Result<Arc<Self::RunningAction>, Error>> + Send; |
2732 | | |
2733 | | fn cache_action_result( |
2734 | | &self, |
2735 | | action_digest: DigestInfo, |
2736 | | action_result: &mut ActionResult, |
2737 | | hasher: DigestHasherFunc, |
2738 | | ) -> impl Future<Output = Result<(), Error>> + Send; |
2739 | | |
2740 | | fn kill_all(&self) -> impl Future<Output = ()> + Send; |
2741 | | |
2742 | | fn kill_operation( |
2743 | | &self, |
2744 | | operation_id: &OperationId, |
2745 | | ) -> impl Future<Output = Result<(), Error>> + Send; |
2746 | | |
2747 | | fn metrics(&self) -> &Arc<Metrics>; |
2748 | | } |
2749 | | |
2750 | | /// A function to get the current system time, used to allow mocking for tests |
2751 | | type NowFn = fn() -> SystemTime; |
2752 | | type SleepFn = fn(Duration) -> BoxFuture<'static, ()>; |
2753 | | |
2754 | | /// Functions that may be injected for testing purposes, during standard control |
2755 | | /// flows these are specified by the new function. |
2756 | | #[derive(Clone, Copy)] |
2757 | | pub struct Callbacks { |
2758 | | /// A function that gets the current time. |
2759 | | pub now_fn: NowFn, |
2760 | | /// A function that sleeps for a given Duration. |
2761 | | pub sleep_fn: SleepFn, |
2762 | | } |
2763 | | |
2764 | | impl Debug for Callbacks { |
2765 | 0 | fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { |
2766 | 0 | f.debug_struct("Callbacks").finish_non_exhaustive() |
2767 | 0 | } |
2768 | | } |
2769 | | |
2770 | | /// The set of additional information for executing an action over and above |
2771 | | /// those given in the `ActionInfo` passed to the worker. This allows |
2772 | | /// modification of the action for execution on this particular worker. This |
2773 | | /// may be used to run the action with a particular set of additional |
2774 | | /// environment variables, or perhaps configure it to execute within a |
2775 | | /// container. |
2776 | | #[derive(Debug, Default)] |
2777 | | pub struct ExecutionConfiguration { |
2778 | | /// If set, will be executed instead of the first argument passed in the |
2779 | | /// `ActionInfo` with all of the arguments in the `ActionInfo` passed as |
2780 | | /// arguments to this command. |
2781 | | pub entrypoint: Option<String>, |
2782 | | /// The only environment variables that will be specified when the command |
2783 | | /// executes other than those in the `ActionInfo`. On Windows, `SystemRoot` |
2784 | | /// and PATH are also assigned (see `inner_execute`). |
2785 | | pub additional_environment: Option<HashMap<String, EnvironmentSource>>, |
2786 | | } |
2787 | | |
2788 | | #[derive(Debug)] |
2789 | | struct UploadActionResults { |
2790 | | upload_ac_results_strategy: UploadCacheResultsStrategy, |
2791 | | upload_historical_results_strategy: UploadCacheResultsStrategy, |
2792 | | ac_store: Option<Store>, |
2793 | | historical_store: Store, |
2794 | | success_message_template: Template, |
2795 | | failure_message_template: Template, |
2796 | | } |
2797 | | |
2798 | | impl UploadActionResults { |
2799 | 37 | fn new( |
2800 | 37 | config: &UploadActionResultConfig, |
2801 | 37 | ac_store: Option<Store>, |
2802 | 37 | historical_store: Store, |
2803 | 37 | ) -> Result<Self, Error> { |
2804 | 37 | let upload_historical_results_strategy = config |
2805 | 37 | .upload_historical_results_strategy |
2806 | 37 | .unwrap_or(DEFAULT_HISTORICAL_RESULTS_STRATEGY); |
2807 | 8 | if !matches!( |
2808 | 37 | config.upload_ac_results_strategy, |
2809 | | UploadCacheResultsStrategy::Never |
2810 | 8 | ) && ac_store.is_none() |
2811 | | { |
2812 | 0 | return Err(make_input_err!( |
2813 | 0 | "upload_ac_results_strategy is set, but no ac_store is configured" |
2814 | 0 | )); |
2815 | 37 | } |
2816 | | Ok(Self { |
2817 | 37 | upload_ac_results_strategy: config.upload_ac_results_strategy, |
2818 | 37 | upload_historical_results_strategy, |
2819 | 37 | ac_store, |
2820 | 37 | historical_store, |
2821 | 37 | success_message_template: Template::new(&config.success_message_template).map_err( |
2822 | 0 | |e| { |
2823 | 0 | Error::from_std_err(Code::InvalidArgument, &e).append(format!( |
2824 | | "Could not convert success_message_template to rust template: {}", |
2825 | | config.success_message_template |
2826 | | )) |
2827 | 0 | }, |
2828 | 0 | )?, |
2829 | 37 | failure_message_template: Template::new(&config.failure_message_template).map_err( |
2830 | 0 | |e| { |
2831 | 0 | Error::from_std_err(Code::InvalidArgument, &e).append(format!( |
2832 | | "Could not convert failure_message_template to rust template: {}", |
2833 | | config.success_message_template |
2834 | | )) |
2835 | 0 | }, |
2836 | 0 | )?, |
2837 | | }) |
2838 | 37 | } |
2839 | | |
2840 | 0 | const fn should_cache_result( |
2841 | 0 | strategy: UploadCacheResultsStrategy, |
2842 | 0 | action_result: &ActionResult, |
2843 | 0 | treat_infra_error_as_failure: bool, |
2844 | 0 | ) -> bool { |
2845 | 0 | let did_fail = action_result.exit_code != 0 |
2846 | 0 | || (treat_infra_error_as_failure && action_result.error.is_some()); |
2847 | 0 | match strategy { |
2848 | 0 | UploadCacheResultsStrategy::SuccessOnly => !did_fail, |
2849 | 0 | UploadCacheResultsStrategy::Never => false, |
2850 | | // Never cache internal errors or timeouts. |
2851 | | UploadCacheResultsStrategy::Everything => { |
2852 | 0 | treat_infra_error_as_failure || action_result.error.is_none() |
2853 | | } |
2854 | 0 | UploadCacheResultsStrategy::FailuresOnly => did_fail, |
2855 | | } |
2856 | 0 | } |
2857 | | |
2858 | | /// Formats the message field in `ExecuteResponse` from the `success_message_template` |
2859 | | /// or `failure_message_template` config templates. |
2860 | 5 | fn format_execute_response_message( |
2861 | 5 | mut template_str: Template, |
2862 | 5 | action_digest_info: DigestInfo, |
2863 | 5 | maybe_historical_digest_info: Option<DigestInfo>, |
2864 | 5 | hasher: DigestHasherFunc, |
2865 | 5 | ) -> Result<String, Error> { |
2866 | 5 | template_str.replace( |
2867 | | "digest_function", |
2868 | 5 | hasher.proto_digest_func().as_str_name().to_lowercase(), |
2869 | | ); |
2870 | 5 | template_str.replace( |
2871 | | "action_digest_hash", |
2872 | 5 | action_digest_info.packed_hash().to_string(), |
2873 | | ); |
2874 | 5 | template_str.replace("action_digest_size", action_digest_info.size_bytes()); |
2875 | 5 | if let Some(historical_digest_info3 ) = maybe_historical_digest_info { |
2876 | 3 | template_str.replace( |
2877 | 3 | "historical_results_hash", |
2878 | 3 | format!("{}", historical_digest_info.packed_hash()), |
2879 | 3 | ); |
2880 | 3 | template_str.replace( |
2881 | 3 | "historical_results_size", |
2882 | 3 | historical_digest_info.size_bytes(), |
2883 | 3 | ); |
2884 | 3 | } else { |
2885 | 2 | template_str.replace("historical_results_hash", ""); |
2886 | 2 | template_str.replace("historical_results_size", ""); |
2887 | 2 | } |
2888 | 5 | template_str.text().map_err(|e| {0 |
2889 | 0 | Error::from_std_err(Code::InvalidArgument, &e) |
2890 | 0 | .append("Could not convert template to text") |
2891 | 0 | }) |
2892 | 5 | } |
2893 | | |
2894 | 0 | async fn upload_ac_results( |
2895 | 0 | &self, |
2896 | 0 | action_digest: DigestInfo, |
2897 | 0 | action_result: ProtoActionResult, |
2898 | 0 | hasher: DigestHasherFunc, |
2899 | 5 | ) -> Result<(), Error> { |
2900 | 5 | let Some(ac_store) = self.ac_store.as_ref() else { |
2901 | 0 | return Ok(()); |
2902 | | }; |
2903 | | // If we are a GrpcStore we shortcut here, as this is a special store. |
2904 | 5 | if let Some(grpc_store0 ) = ac_store.downcast_ref::<GrpcStore>(Some(action_digest.into())) { |
2905 | 0 | let update_action_request = UpdateActionResultRequest { |
2906 | 0 | // This is populated by `update_action_result`. |
2907 | 0 | instance_name: String::new(), |
2908 | 0 | action_digest: Some(action_digest.into()), |
2909 | 0 | action_result: Some(action_result), |
2910 | 0 | results_cache_policy: None, |
2911 | 0 | digest_function: hasher.proto_digest_func().into(), |
2912 | 0 | }; |
2913 | 0 | return grpc_store |
2914 | 0 | .update_action_result(Request::new(update_action_request)) |
2915 | 0 | .await |
2916 | 0 | .map(|_| ()) |
2917 | 0 | .err_tip(|| "Caching ActionResult"); |
2918 | 5 | } |
2919 | | |
2920 | 5 | let mut store_data = BytesMut::with_capacity(ESTIMATED_DIGEST_SIZE); |
2921 | 5 | action_result |
2922 | 5 | .encode(&mut store_data) |
2923 | 5 | .err_tip(|| "Encoding ActionResult for caching")?0 ; |
2924 | | |
2925 | 5 | ac_store |
2926 | 5 | .update_oneshot(action_digest, store_data.split().freeze()) |
2927 | 5 | .await |
2928 | 5 | .err_tip(|| "Caching ActionResult") |
2929 | 5 | } |
2930 | | |
2931 | 3 | async fn upload_historical_results_with_message( |
2932 | 3 | &self, |
2933 | 3 | action_digest: DigestInfo, |
2934 | 3 | execute_response: ExecuteResponse, |
2935 | 3 | message_template: Template, |
2936 | 3 | hasher: DigestHasherFunc, |
2937 | 3 | ) -> Result<String, Error> { |
2938 | 3 | let historical_digest_info = serialize_and_upload_message( |
2939 | 3 | &HistoricalExecuteResponse { |
2940 | 3 | action_digest: Some(action_digest.into()), |
2941 | 3 | execute_response: Some(execute_response.clone()), |
2942 | 3 | }, |
2943 | 3 | self.historical_store.as_pin(), |
2944 | 3 | &mut hasher.hasher(), |
2945 | 3 | ) |
2946 | 3 | .await |
2947 | 3 | .err_tip(|| format!0 ("Caching HistoricalExecuteResponse for digest: {action_digest}"))?0 ; |
2948 | | |
2949 | 3 | Self::format_execute_response_message( |
2950 | 3 | message_template, |
2951 | 3 | action_digest, |
2952 | 3 | Some(historical_digest_info), |
2953 | 3 | hasher, |
2954 | | ) |
2955 | 3 | .err_tip(|| "Could not format message in upload_historical_results_with_message") |
2956 | 3 | } |
2957 | | |
2958 | 0 | async fn cache_action_result( |
2959 | 0 | &self, |
2960 | 0 | action_info: DigestInfo, |
2961 | 0 | action_result: &mut ActionResult, |
2962 | 0 | hasher: DigestHasherFunc, |
2963 | 6 | ) -> Result<(), Error> { |
2964 | 6 | let should_upload_historical_results = |
2965 | 6 | Self::should_cache_result(self.upload_historical_results_strategy, action_result, true); |
2966 | 6 | let should_upload_ac_results = |
2967 | 6 | Self::should_cache_result(self.upload_ac_results_strategy, action_result, false); |
2968 | | // Shortcut so we don't need to convert to proto if not needed. |
2969 | 6 | if !should_upload_ac_results && !should_upload_historical_results1 { |
2970 | 1 | return Ok(()); |
2971 | 5 | } |
2972 | | |
2973 | 5 | let mut execute_response = to_execute_response(action_result.clone()); |
2974 | | |
2975 | | // In theory exit code should always be != 0 if there's an error, but for safety we |
2976 | | // catch both. |
2977 | 5 | let message_template = if action_result.exit_code == 0 && action_result.error4 .is_none4 () { |
2978 | 3 | self.success_message_template.clone() |
2979 | | } else { |
2980 | 2 | self.failure_message_template.clone() |
2981 | | }; |
2982 | | |
2983 | 5 | let upload_historical_results_with_message_result = if should_upload_historical_results { |
2984 | 3 | let maybe_message = self |
2985 | 3 | .upload_historical_results_with_message( |
2986 | 3 | action_info, |
2987 | 3 | execute_response.clone(), |
2988 | 3 | message_template, |
2989 | 3 | hasher, |
2990 | 3 | ) |
2991 | 3 | .await; |
2992 | 3 | match maybe_message { |
2993 | 3 | Ok(message) => { |
2994 | 3 | action_result.message.clone_from(&message); |
2995 | 3 | execute_response.message = message; |
2996 | 3 | Ok(()) |
2997 | | } |
2998 | 0 | Err(e) => Result::<(), Error>::Err(e), |
2999 | | } |
3000 | | } else { |
3001 | 2 | match Self::format_execute_response_message(message_template, action_info, None, hasher) |
3002 | | { |
3003 | 2 | Ok(message) => { |
3004 | 2 | action_result.message.clone_from(&message); |
3005 | 2 | execute_response.message = message; |
3006 | 2 | Ok(()) |
3007 | | } |
3008 | 0 | Err(e) => Err(e).err_tip(|| "Could not format message in cache_action_result"), |
3009 | | } |
3010 | | }; |
3011 | | |
3012 | | // Note: Done in this order because we assume most results will succeed and most configs will |
3013 | | // either always upload upload historical results or only upload on failure. In which case |
3014 | | // we can avoid an extra clone of the protos by doing this last with the above assumption. |
3015 | 5 | let ac_upload_results = if should_upload_ac_results { |
3016 | 5 | self.upload_ac_results( |
3017 | 5 | action_info, |
3018 | 5 | execute_response |
3019 | 5 | .result |
3020 | 5 | .err_tip(|| "No result set in cache_action_result")?0 , |
3021 | 5 | hasher, |
3022 | | ) |
3023 | 5 | .await |
3024 | | } else { |
3025 | 0 | Ok(()) |
3026 | | }; |
3027 | 5 | upload_historical_results_with_message_result.merge(ac_upload_results) |
3028 | 6 | } |
3029 | | } |
3030 | | |
3031 | | #[cfg(target_os = "linux")] |
3032 | | #[derive(Copy, Clone, Debug)] |
3033 | | pub enum UseNamespaces { |
3034 | | No, |
3035 | | Yes, |
3036 | | YesAndMount, |
3037 | | } |
3038 | | |
3039 | | #[derive(Debug)] |
3040 | | pub struct RunningActionsManagerArgs<'a> { |
3041 | | pub root_action_directory: String, |
3042 | | pub execution_configuration: ExecutionConfiguration, |
3043 | | pub cas_store: Arc<FastSlowStore>, |
3044 | | pub ac_store: Option<Store>, |
3045 | | pub historical_store: Store, |
3046 | | pub upload_action_result_config: &'a UploadActionResultConfig, |
3047 | | pub max_action_timeout: Duration, |
3048 | | pub max_upload_timeout: Duration, |
3049 | | pub max_cleanup_wait: Duration, |
3050 | | pub max_cleanup_backoff: Duration, |
3051 | | pub timeout_handled_externally: bool, |
3052 | | pub directory_cache: Option<Arc<crate::directory_cache::DirectoryCache>>, |
3053 | | /// When true, every digest in an active action's input Merkle closure is |
3054 | | /// leased in the locally eviction-managed CAS tiers until the action's |
3055 | | /// cleanup completes. While leases are held, those tiers may temporarily |
3056 | | /// exceed their configured `max_bytes` / `max_count` eviction limits. |
3057 | | pub active_input_leases: bool, |
3058 | | #[cfg(target_os = "linux")] |
3059 | | pub use_namespaces: UseNamespaces, |
3060 | | } |
3061 | | |
3062 | | struct CleanupGuard { |
3063 | | manager: Weak<RunningActionsManagerImpl>, |
3064 | | operation_id: OperationId, |
3065 | | } |
3066 | | |
3067 | | impl Drop for CleanupGuard { |
3068 | 226 | fn drop(&mut self) { |
3069 | 226 | let Some(manager) = self.manager.upgrade() else { |
3070 | 0 | return; |
3071 | | }; |
3072 | 226 | let mut cleaning = manager.cleaning_up_operations.lock(); |
3073 | 226 | cleaning.remove(&self.operation_id); |
3074 | 226 | manager.cleanup_complete_notify.notify_waiters(); |
3075 | 226 | } |
3076 | | } |
3077 | | |
3078 | | /// Holds state info about what is being executed and the interface for interacting |
3079 | | /// with actions while they are running. |
3080 | | #[derive(Debug)] |
3081 | | pub struct RunningActionsManagerImpl { |
3082 | | root_action_directory: String, |
3083 | | execution_configuration: ExecutionConfiguration, |
3084 | | cas_store: Arc<FastSlowStore>, |
3085 | | filesystem_store: Arc<FilesystemStore>, |
3086 | | upload_action_results: UploadActionResults, |
3087 | | max_action_timeout: Duration, |
3088 | | max_upload_timeout: Duration, |
3089 | | timeout_handled_externally: bool, |
3090 | | #[cfg(target_os = "linux")] |
3091 | | use_namespaces: UseNamespaces, |
3092 | | running_actions: Mutex<HashMap<OperationId, Weak<RunningActionImpl>>>, |
3093 | | // Note: We don't use Notify because we need to support a .wait_for()-like function, which |
3094 | | // Notify does not support. |
3095 | | action_done_tx: watch::Sender<()>, |
3096 | | callbacks: Callbacks, |
3097 | | metrics: Arc<Metrics>, |
3098 | | /// Track operations being cleaned up to avoid directory collisions during action retries. |
3099 | | /// When an action fails and is retried on the same worker, we need to ensure the previous |
3100 | | /// attempt's directory is fully cleaned up before creating a new one. |
3101 | | /// See: <https://github.com/TraceMachina/nativelink/issues/1859> |
3102 | | cleaning_up_operations: Mutex<HashSet<OperationId>>, |
3103 | | max_cleanup_wait: Duration, |
3104 | | max_cleanup_backoff: Duration, |
3105 | | /// Notify waiters when a cleanup operation completes. This is used in conjunction with |
3106 | | /// `cleaning_up_operations` to coordinate directory cleanup and creation. |
3107 | | cleanup_complete_notify: Arc<Notify>, |
3108 | | /// Optional directory cache for improving performance by caching reconstructed |
3109 | | /// input directories and using hardlinks. |
3110 | | directory_cache: Option<Arc<crate::directory_cache::DirectoryCache>>, |
3111 | | /// Whether active action inputs are leased against eviction in the local |
3112 | | /// CAS tiers (opt-in via `experimental_active_input_leases`). |
3113 | | active_input_leases: bool, |
3114 | | persistent_worker_pool: PersistentWorkerPool, |
3115 | | } |
3116 | | |
3117 | | impl RunningActionsManagerImpl { |
3118 | 37 | pub fn new_with_callbacks( |
3119 | 37 | args: RunningActionsManagerArgs<'_>, |
3120 | 37 | callbacks: Callbacks, |
3121 | 37 | ) -> Result<Self, Error> { |
3122 | | // Sadly because of some limitations of how Any works we need to clone more times than optimal. |
3123 | 37 | let filesystem_store = args |
3124 | 37 | .cas_store |
3125 | 37 | .fast_store() |
3126 | 37 | .downcast_ref::<FilesystemStore>(None) |
3127 | 37 | .err_tip( |
3128 | | || "Expected FilesystemStore store for .fast_store() in RunningActionsManagerImpl", |
3129 | 0 | )? |
3130 | 37 | .get_arc() |
3131 | 37 | .err_tip(|| "FilesystemStore's internal Arc was lost")?0 ; |
3132 | 37 | let (action_done_tx, _) = watch::channel(()); |
3133 | | Ok(Self { |
3134 | 37 | root_action_directory: args.root_action_directory, |
3135 | 37 | execution_configuration: args.execution_configuration, |
3136 | 37 | cas_store: args.cas_store, |
3137 | 37 | filesystem_store, |
3138 | 37 | upload_action_results: UploadActionResults::new( |
3139 | 37 | args.upload_action_result_config, |
3140 | 37 | args.ac_store, |
3141 | 37 | args.historical_store, |
3142 | | ) |
3143 | 37 | .err_tip(|| "During RunningActionsManagerImpl construction")?0 , |
3144 | 37 | max_action_timeout: args.max_action_timeout, |
3145 | 37 | max_upload_timeout: args.max_upload_timeout, |
3146 | 37 | timeout_handled_externally: args.timeout_handled_externally, |
3147 | 37 | running_actions: Mutex::new(HashMap::new()), |
3148 | 37 | action_done_tx, |
3149 | 37 | callbacks, |
3150 | 37 | metrics: Arc::new(Metrics { |
3151 | 37 | directory_cache: args.directory_cache.as_ref().map(Arc::downgrade), |
3152 | 37 | ..Default::default() |
3153 | 37 | }), |
3154 | 37 | cleaning_up_operations: Mutex::new(HashSet::new()), |
3155 | 37 | max_cleanup_wait: args.max_cleanup_wait, |
3156 | 37 | max_cleanup_backoff: args.max_cleanup_backoff, |
3157 | 37 | cleanup_complete_notify: Arc::new(Notify::new()), |
3158 | 37 | directory_cache: args.directory_cache, |
3159 | 37 | active_input_leases: args.active_input_leases, |
3160 | 37 | persistent_worker_pool: PersistentWorkerPool::default(), |
3161 | | #[cfg(target_os = "linux")] |
3162 | 37 | use_namespaces: args.use_namespaces, |
3163 | | }) |
3164 | 37 | } |
3165 | | |
3166 | 15 | pub fn new(args: RunningActionsManagerArgs<'_>) -> Result<Self, Error> { |
3167 | 15 | Self::new_with_callbacks( |
3168 | 15 | args, |
3169 | | Callbacks { |
3170 | 15 | now_fn: SystemTime::now, |
3171 | 2 | sleep_fn: |duration| Box::pin(tokio::time::sleep(duration)), |
3172 | | }, |
3173 | | ) |
3174 | 15 | } |
3175 | | |
3176 | | /// Fixes a race condition that occurs when an action fails to execute on a worker, and the same worker |
3177 | | /// attempts to re-execute the same action before the physical cleanup (file is removed) completes. |
3178 | | /// See this issue for additional details: <https://github.com/TraceMachina/nativelink/issues/1859> |
3179 | 231 | async fn wait_for_cleanup_if_needed(&self, operation_id: &OperationId) -> Result<(), Error>0 { |
3180 | 231 | let start = Instant::now(); |
3181 | 231 | let mut backoff = Duration::from_millis(10); |
3182 | 231 | let mut has_waited = false; |
3183 | | |
3184 | | loop { |
3185 | 231 | let should_wait = { |
3186 | 231 | let cleaning = self.cleaning_up_operations.lock(); |
3187 | 231 | cleaning.contains(operation_id) |
3188 | | }; |
3189 | | |
3190 | 231 | if !should_wait { |
3191 | 231 | let action_is_running = self |
3192 | 231 | .running_actions |
3193 | 231 | .lock() |
3194 | 231 | .get(operation_id) |
3195 | 231 | .and_then(Weak::upgrade) |
3196 | 231 | .is_some(); |
3197 | 231 | if action_is_running { |
3198 | 1 | return Err(make_err!( |
3199 | 1 | Code::AlreadyExists, |
3200 | 1 | "Action with operation_id {} is already running", |
3201 | 1 | operation_id |
3202 | 1 | )); |
3203 | 230 | } |
3204 | | |
3205 | 230 | let dir_path = |
3206 | 230 | PathBuf::from(&self.root_action_directory).join(operation_id.to_string()); |
3207 | | |
3208 | 230 | if !dir_path.exists() { |
3209 | 229 | return Ok(()); |
3210 | 1 | } |
3211 | | |
3212 | | // Safety check: ensure we're only removing directories under root_action_directory |
3213 | 1 | let root_path = Path::new(&self.root_action_directory); |
3214 | 1 | let canonical_root = root_path.canonicalize().err_tip(|| {0 |
3215 | 0 | format!( |
3216 | | "Failed to canonicalize root directory: {}", |
3217 | | self.root_action_directory |
3218 | | ) |
3219 | 0 | })?; |
3220 | 1 | let canonical_dir = dir_path.canonicalize().err_tip(|| {0 |
3221 | 0 | format!("Failed to canonicalize directory: {}", dir_path.display()) |
3222 | 0 | })?; |
3223 | | |
3224 | 1 | if !canonical_dir.starts_with(&canonical_root) { |
3225 | 0 | return Err(make_err!( |
3226 | 0 | Code::Internal, |
3227 | 0 | "Attempted to remove directory outside of root_action_directory: {}", |
3228 | 0 | dir_path.display() |
3229 | 0 | )); |
3230 | 1 | } |
3231 | | |
3232 | | // Directory exists but not being cleaned - remove it |
3233 | 1 | warn!( |
3234 | | "Removing stale directory for {}: {}", |
3235 | | operation_id, |
3236 | 1 | dir_path.display() |
3237 | | ); |
3238 | 1 | self.metrics.stale_removals.inc(); |
3239 | | |
3240 | | // Try to remove the directory, with one retry on failure |
3241 | 1 | let remove_result = fs::remove_dir_all(&dir_path).await; |
3242 | 1 | if let Err(e0 ) = remove_result { |
3243 | | // Retry once after a short delay in case the directory is temporarily locked |
3244 | 0 | tokio::time::sleep(Duration::from_millis(100)).await; |
3245 | 0 | fs::remove_dir_all(&dir_path).await.err_tip(|| { |
3246 | 0 | format!( |
3247 | | "Failed to remove stale directory {} for retry of {} after retry (original error: {})", |
3248 | 0 | dir_path.display(), |
3249 | | operation_id, |
3250 | | e |
3251 | | ) |
3252 | 0 | })?; |
3253 | 1 | } |
3254 | 1 | return Ok(()); |
3255 | 0 | } |
3256 | | |
3257 | 0 | if start.elapsed() > self.max_cleanup_wait { |
3258 | 0 | self.metrics.cleanup_wait_timeouts.inc(); |
3259 | 0 | warn!(%operation_id, waited=?start.elapsed(), "Timeout waiting for previous operation cleanup"); |
3260 | 0 | return Err(make_err!( |
3261 | 0 | Code::DeadlineExceeded, |
3262 | 0 | "Timeout waiting for previous operation cleanup: {} (waited {:?})", |
3263 | 0 | operation_id, |
3264 | 0 | start.elapsed() |
3265 | 0 | )); |
3266 | 0 | } |
3267 | | |
3268 | 0 | if !has_waited { |
3269 | 0 | self.metrics.cleanup_waits.inc(); |
3270 | 0 | has_waited = true; |
3271 | 0 | } |
3272 | | |
3273 | 0 | trace!( |
3274 | | "Waiting for cleanup of {} (elapsed: {:?}, backoff: {:?})", |
3275 | | operation_id, |
3276 | 0 | start.elapsed(), |
3277 | | backoff |
3278 | | ); |
3279 | | |
3280 | 0 | tokio::select! { |
3281 | 0 | () = self.cleanup_complete_notify.notified() => {}, |
3282 | 0 | () = tokio::time::sleep(backoff) => { |
3283 | 0 | // Exponential backoff |
3284 | 0 | backoff = (backoff * 2).min(self.max_cleanup_backoff); |
3285 | 0 | }, |
3286 | | } |
3287 | | } |
3288 | 231 | } |
3289 | | |
3290 | 0 | fn make_action_directory<'a>( |
3291 | 0 | &'a self, |
3292 | 0 | operation_id: &'a OperationId, |
3293 | 0 | ) -> impl Future<Output = Result<String, Error>> + 'a { |
3294 | 230 | self.metrics.make_action_directory0 .wrap0 (async move { |
3295 | 230 | let action_directory = format!("{}/{}", self.root_action_directory, operation_id); |
3296 | 230 | fs::create_dir(&action_directory) |
3297 | 230 | .await |
3298 | 230 | .err_tip(|| format!0 ("Error creating action directory {action_directory}"))?0 ; |
3299 | 230 | Ok(action_directory) |
3300 | 230 | }) |
3301 | 0 | } |
3302 | | |
3303 | 231 | fn create_action_info( |
3304 | 231 | &self, |
3305 | 231 | start_execute: StartExecute, |
3306 | 231 | queued_timestamp: SystemTime, |
3307 | 231 | ) -> impl Future<Output = Result<ActionInfo, Error>> + '_ { |
3308 | 231 | self.metrics.create_action_info.wrap(async move { |
3309 | 231 | let execute_request = start_execute |
3310 | 231 | .execute_request |
3311 | 231 | .err_tip(|| "Expected execute_request to exist in StartExecute")?0 ; |
3312 | 231 | let action_digest: DigestInfo = execute_request |
3313 | 231 | .action_digest |
3314 | 231 | .clone() |
3315 | 231 | .err_tip(|| "Expected action_digest to exist on StartExecute")?0 |
3316 | 231 | .try_into()?0 ; |
3317 | 231 | let load_start_timestamp = (self.callbacks.now_fn)(); |
3318 | 231 | let action = |
3319 | 231 | get_and_decode_digest::<Action>(self.cas_store.as_ref(), action_digest.into()) |
3320 | 231 | .await |
3321 | 231 | .err_tip(|| "During start_action")?0 ; |
3322 | 231 | let action_info = ActionInfo::try_from_action_and_execute_request( |
3323 | 231 | execute_request, |
3324 | 231 | action, |
3325 | 231 | load_start_timestamp, |
3326 | 231 | queued_timestamp, |
3327 | | ) |
3328 | 231 | .err_tip(|| "Could not create ActionInfo in create_and_add_action()")?0 ; |
3329 | 231 | Ok(action_info) |
3330 | 231 | }) |
3331 | 231 | } |
3332 | | |
3333 | 228 | fn cleanup_action(&self, operation_id: &OperationId) -> Result<(), Error> { |
3334 | | // The guard must be dropped before notifying: `send_modify` takes |
3335 | | // the watch channel's internal lock, and a `wait_for` closure that |
3336 | | // takes `running_actions` runs while holding that same lock, so |
3337 | | // notifying while holding `running_actions` is an ABBA deadlock |
3338 | | // (issue #2672). There is no lost wakeup in the gap: the removal |
3339 | | // happens-before the notify. |
3340 | 228 | let result = { |
3341 | 228 | let mut running_actions = self.running_actions.lock(); |
3342 | 228 | running_actions.remove(operation_id).err_tip(|| {0 |
3343 | 0 | format!( |
3344 | | "Expected operation id '{operation_id}' to exist in RunningActionsManagerImpl" |
3345 | | ) |
3346 | 0 | }) |
3347 | | }; |
3348 | | // No need to copy anything, we just are telling the receivers an event happened. |
3349 | 228 | self.action_done_tx.send_modify(|()| {}); |
3350 | 228 | result.map(|_| ()) |
3351 | 228 | } |
3352 | | |
3353 | | // Note: We do not capture metrics on this call, only `.kill_all()`. |
3354 | | // Important: When the future returns the process may still be running. |
3355 | 202 | async fn kill_operation(action: Arc<RunningActionImpl>) { |
3356 | 202 | warn!( |
3357 | 202 | operation_id = ?action.operation_id, |
3358 | | "Sending kill to running operation", |
3359 | | ); |
3360 | 202 | let kill_channel_tx = { |
3361 | 202 | let mut action_state = action.state.lock(); |
3362 | 202 | action_state.kill_channel_tx.take() |
3363 | | }; |
3364 | 202 | if let Some(kill_channel_tx) = kill_channel_tx |
3365 | 202 | && kill_channel_tx.send(()).is_err() |
3366 | | { |
3367 | 0 | error!( |
3368 | 0 | operation_id = ?action.operation_id, |
3369 | | "Error sending kill to running operation", |
3370 | | ); |
3371 | 202 | } |
3372 | 202 | } |
3373 | | |
3374 | 226 | fn perform_cleanup(self: &Arc<Self>, operation_id: OperationId) -> Option<CleanupGuard> { |
3375 | 226 | let mut cleaning = self.cleaning_up_operations.lock(); |
3376 | 226 | cleaning |
3377 | 226 | .insert(operation_id.clone()) |
3378 | 226 | .then_some(CleanupGuard { |
3379 | 226 | manager: Arc::downgrade(self), |
3380 | 226 | operation_id, |
3381 | 226 | }) |
3382 | 226 | } |
3383 | | } |
3384 | | |
3385 | | impl RunningActionsManager for RunningActionsManagerImpl { |
3386 | | type RunningAction = RunningActionImpl; |
3387 | | |
3388 | 0 | async fn create_and_add_action( |
3389 | 0 | self: &Arc<Self>, |
3390 | 0 | worker_id: String, |
3391 | 0 | start_execute: StartExecute, |
3392 | 231 | ) -> Result<Arc<RunningActionImpl>, Error> { |
3393 | 231 | self.metrics |
3394 | 231 | .create_and_add_action |
3395 | 231 | .wrap(async move { |
3396 | 231 | let queued_timestamp = start_execute |
3397 | 231 | .queued_timestamp |
3398 | 231 | .and_then(|time| time216 .try_into216 ().ok216 ()) |
3399 | 231 | .unwrap_or(SystemTime::UNIX_EPOCH); |
3400 | 231 | let operation_id = start_execute |
3401 | 231 | .operation_id.as_str().into(); |
3402 | 231 | let action_info = self.create_action_info(start_execute, queued_timestamp).await?0 ; |
3403 | 231 | debug!( |
3404 | | ?action_info, |
3405 | | "Worker received action", |
3406 | | ); |
3407 | | // Wait for any previous cleanup to complete before creating directory |
3408 | 231 | self.wait_for_cleanup_if_needed(&operation_id).await?1 ; |
3409 | 230 | let action_directory = self.make_action_directory(&operation_id).await?0 ; |
3410 | 230 | let execution_metadata = ExecutionMetadata { |
3411 | 230 | worker: worker_id, |
3412 | 230 | queued_timestamp: action_info.insert_timestamp, |
3413 | 230 | worker_start_timestamp: action_info.load_timestamp, |
3414 | 230 | worker_completed_timestamp: SystemTime::UNIX_EPOCH, |
3415 | 230 | input_fetch_start_timestamp: SystemTime::UNIX_EPOCH, |
3416 | 230 | input_fetch_completed_timestamp: SystemTime::UNIX_EPOCH, |
3417 | 230 | execution_start_timestamp: SystemTime::UNIX_EPOCH, |
3418 | 230 | execution_completed_timestamp: SystemTime::UNIX_EPOCH, |
3419 | 230 | output_upload_start_timestamp: SystemTime::UNIX_EPOCH, |
3420 | 230 | output_upload_completed_timestamp: SystemTime::UNIX_EPOCH, |
3421 | 230 | }; |
3422 | 230 | let timeout = if action_info.timeout.is_zero() || self.timeout_handled_externally3 { |
3423 | 227 | self.max_action_timeout |
3424 | | } else { |
3425 | 3 | action_info.timeout |
3426 | | }; |
3427 | 230 | if timeout > self.max_action_timeout { |
3428 | 1 | return Err(make_err!( |
3429 | 1 | Code::InvalidArgument, |
3430 | 1 | "Action timeout of {} seconds is greater than the maximum allowed timeout of {} seconds", |
3431 | 1 | timeout.as_secs_f32(), |
3432 | 1 | self.max_action_timeout.as_secs_f32() |
3433 | 1 | )); |
3434 | 229 | } |
3435 | 229 | let running_action = Arc::new(RunningActionImpl::new( |
3436 | 229 | execution_metadata, |
3437 | 229 | operation_id.clone(), |
3438 | 229 | action_directory, |
3439 | 229 | action_info, |
3440 | 229 | timeout, |
3441 | 229 | self.clone(), |
3442 | | )); |
3443 | | { |
3444 | 229 | let mut running_actions = self.running_actions.lock(); |
3445 | | // Check if action already exists and is still alive |
3446 | 229 | if let Some(existing_weak0 ) = running_actions.get(&operation_id) |
3447 | 0 | && let Some(_existing_action) = existing_weak.upgrade() { |
3448 | 0 | return Err(make_err!( |
3449 | 0 | Code::AlreadyExists, |
3450 | 0 | "Action with operation_id {} is already running", |
3451 | 0 | operation_id |
3452 | 0 | )); |
3453 | 229 | } |
3454 | 229 | running_actions.insert(operation_id, Arc::downgrade(&running_action)); |
3455 | 229 | running_action |
3456 | 229 | .has_manager_entry |
3457 | 229 | .store(true, Ordering::Release); |
3458 | | } |
3459 | 229 | Ok(running_action) |
3460 | 231 | }) |
3461 | 231 | .await |
3462 | 231 | } |
3463 | | |
3464 | 0 | async fn cache_action_result( |
3465 | 0 | &self, |
3466 | 0 | action_info: DigestInfo, |
3467 | 0 | action_result: &mut ActionResult, |
3468 | 0 | hasher: DigestHasherFunc, |
3469 | 6 | ) -> Result<(), Error> { |
3470 | 6 | self.metrics |
3471 | 6 | .cache_action_result |
3472 | 6 | .wrap(self.upload_action_results.cache_action_result( |
3473 | 6 | action_info, |
3474 | 6 | action_result, |
3475 | 6 | hasher, |
3476 | 6 | )) |
3477 | 6 | .await |
3478 | 6 | } |
3479 | | |
3480 | 0 | async fn kill_operation(&self, operation_id: &OperationId) -> Result<(), Error> { |
3481 | 0 | let running_action = { |
3482 | 0 | let running_actions = self.running_actions.lock(); |
3483 | 0 | running_actions |
3484 | 0 | .get(operation_id) |
3485 | 0 | .and_then(Weak::upgrade) |
3486 | 0 | .ok_or_else(|| make_input_err!("Failed to get running action {operation_id}"))? |
3487 | | }; |
3488 | 0 | Self::kill_operation(running_action).await; |
3489 | 0 | Ok(()) |
3490 | 0 | } |
3491 | | |
3492 | | // Note: When the future returns the process should be fully killed and cleaned up. |
3493 | 52 | async fn kill_all(&self) { |
3494 | 52 | self.metrics |
3495 | 52 | .kill_all |
3496 | 52 | .wrap_no_capture_result(async move { |
3497 | 52 | let kill_operations: Vec<Arc<RunningActionImpl>> = { |
3498 | 52 | let running_actions = self.running_actions.lock(); |
3499 | 52 | running_actions.values().filter_map(Weak::upgrade).collect() |
3500 | | }; |
3501 | 52 | let mut kill_futures: FuturesUnordered<_> = kill_operations |
3502 | 52 | .into_iter() |
3503 | 52 | .map(Self::kill_operation) |
3504 | 52 | .collect(); |
3505 | 254 | while kill_futures.next().await.is_some() {}202 |
3506 | 52 | }) |
3507 | 52 | .await; |
3508 | | // Wait for the running actions to drain. Deliberately NOT |
3509 | | // `wait_for(|()| ...)`: that closure runs while the watch channel's |
3510 | | // internal lock is held, so taking `running_actions` inside it |
3511 | | // deadlocks with anyone notifying the channel while holding |
3512 | | // `running_actions` (issue #2672). Checking outside the channel's |
3513 | | // lock loses no wakeup: `changed()` reports any version bump since |
3514 | | // the last check, and `cleanup_action` removes before it notifies. |
3515 | 52 | let mut action_done_rx = self.action_done_tx.subscribe(); |
3516 | | loop { |
3517 | 177 | if self.running_actions.lock().is_empty() { |
3518 | 52 | break; |
3519 | 125 | } |
3520 | | // The only sender lives on `self`, so this cannot error; if it |
3521 | | // ever did, giving up the wait is still the safe answer. |
3522 | 125 | if action_done_rx.changed().await.is_err() { |
3523 | 0 | break; |
3524 | 125 | } |
3525 | | } |
3526 | 52 | } |
3527 | | |
3528 | | #[inline] |
3529 | 2 | fn metrics(&self) -> &Arc<Metrics> { |
3530 | 2 | &self.metrics |
3531 | 2 | } |
3532 | | } |
3533 | | |
3534 | | #[derive(Debug, Default, MetricsComponent)] |
3535 | | pub struct Metrics { |
3536 | | #[metric(help = "Stats about the create_and_add_action command.")] |
3537 | | create_and_add_action: AsyncCounterWrapper, |
3538 | | #[metric(help = "Stats about the cache_action_result command.")] |
3539 | | cache_action_result: AsyncCounterWrapper, |
3540 | | #[metric(help = "Stats about the kill_all command.")] |
3541 | | kill_all: AsyncCounterWrapper, |
3542 | | #[metric(help = "Stats about the create_action_info command.")] |
3543 | | create_action_info: AsyncCounterWrapper, |
3544 | | #[metric(help = "Stats about the make_work_directory command.")] |
3545 | | make_action_directory: AsyncCounterWrapper, |
3546 | | #[metric(help = "Stats about the prepare_action command.")] |
3547 | | prepare_action: AsyncCounterWrapper, |
3548 | | #[metric(help = "Stats about the execute command.")] |
3549 | | execute: AsyncCounterWrapper, |
3550 | | #[metric(help = "Stats about the upload_results command.")] |
3551 | | upload_results: AsyncCounterWrapper, |
3552 | | #[metric(help = "Stats about the cleanup command.")] |
3553 | | cleanup: AsyncCounterWrapper, |
3554 | | #[metric(help = "Stats about the get_finished_result command.")] |
3555 | | get_finished_result: AsyncCounterWrapper, |
3556 | | #[metric(help = "Number of times an action waited for cleanup to complete.")] |
3557 | | cleanup_waits: CounterWithTime, |
3558 | | #[metric(help = "Number of stale directories removed during action retries.")] |
3559 | | stale_removals: CounterWithTime, |
3560 | | #[metric(help = "Number of timeouts while waiting for cleanup to complete.")] |
3561 | | cleanup_wait_timeouts: CounterWithTime, |
3562 | | #[metric(help = "Stats about the get_proto_command_from_store command.")] |
3563 | | get_proto_command_from_store: AsyncCounterWrapper, |
3564 | | #[metric(help = "Stats about the download_to_directory command.")] |
3565 | | download_to_directory: AsyncCounterWrapper, |
3566 | | #[metric(help = "Stats about the prepare_output_files command.")] |
3567 | | prepare_output_files: AsyncCounterWrapper, |
3568 | | #[metric(help = "Stats about the prepare_output_paths command.")] |
3569 | | prepare_output_paths: AsyncCounterWrapper, |
3570 | | #[metric(help = "Stats about the child_process command.")] |
3571 | | child_process: AsyncCounterWrapper, |
3572 | | #[metric(help = "Stats about the child_process_success_error_code command.")] |
3573 | | child_process_success_error_code: CounterWithTime, |
3574 | | #[metric(help = "Stats about the child_process_failure_error_code command.")] |
3575 | | child_process_failure_error_code: CounterWithTime, |
3576 | | #[metric(help = "Total time spent uploading stdout.")] |
3577 | | upload_stdout: AsyncCounterWrapper, |
3578 | | #[metric(help = "Total time spent uploading stderr.")] |
3579 | | upload_stderr: AsyncCounterWrapper, |
3580 | | #[metric(help = "Total number of task timeouts.")] |
3581 | | task_timeouts: CounterWithTime, |
3582 | | #[metric( |
3583 | | help = "Stats about the input-directory cache (hits, misses, subtree reuse, evictions, size)." |
3584 | | )] |
3585 | | directory_cache: Option<Weak<crate::directory_cache::DirectoryCache>>, |
3586 | | } |