diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index f066d8a1..ce298aad 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -48,7 +48,9 @@ jobs: linux-library: name: Linux library tests (${{ matrix.shard }}) needs: nix-package - runs-on: ubuntu-latest + # Ubuntu 26.04 shards exceeded the 45-minute job timeout mid-test; keep + # 24.04 (last within budget) until 26.04 test runtime fits the timeout. + runs-on: ubuntu-24.04 timeout-minutes: 45 strategy: fail-fast: false @@ -297,7 +299,9 @@ jobs: linux-integration: name: Linux integration tests needs: nix-package - runs-on: ubuntu-latest + # Ubuntu 26.04 hits the candidate-validation readiness timeout; keep the + # last verified image until its sandbox startup behavior is qualified. + runs-on: ubuntu-24.04 timeout-minutes: 45 steps: - name: Check out repository diff --git a/Cargo.lock b/Cargo.lock index 365da7a4..1b24d800 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -661,9 +661,9 @@ dependencies = [ [[package]] name = "ctutils" -version = "0.4.2" +version = "0.4.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7d5515a3834141de9eafb9717ad39eea8247b5674e6066c404e8c4b365d2a29e" +checksum = "12218662ccac37d9714f2191252553d67585b97df8c839cbe49e0bde278dc865" dependencies = [ "cmov", ] @@ -2436,9 +2436,9 @@ checksum = "1f3ccbac311fea05f86f61904b462b55fb3df8837a366dfc601a0161d0532f20" [[package]] name = "tokio" -version = "1.53.1" +version = "1.53.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "202caea871b69668250d242070849eb495be178ed697a3e98aebce5bc81a0bed" +checksum = "ce3335fa71841cda333a58d7615b03901380ecf09d59b3296d21f8bbac0dde4e" dependencies = [ "bytes", "libc", diff --git a/account-manager/src-tauri/Cargo.lock b/account-manager/src-tauri/Cargo.lock index 6294ec8d..30dd7055 100644 --- a/account-manager/src-tauri/Cargo.lock +++ b/account-manager/src-tauri/Cargo.lock @@ -904,9 +904,9 @@ checksum = "914a755b7c2d4af2bdcff7ce1739e2db9a1b81a9b07123d8015786ae03c0980d" [[package]] name = "ctutils" -version = "0.4.2" +version = "0.4.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7d5515a3834141de9eafb9717ad39eea8247b5674e6066c404e8c4b365d2a29e" +checksum = "12218662ccac37d9714f2191252553d67585b97df8c839cbe49e0bde278dc865" dependencies = [ "cmov", ] @@ -4556,9 +4556,9 @@ checksum = "1f3ccbac311fea05f86f61904b462b55fb3df8837a366dfc601a0161d0532f20" [[package]] name = "tokio" -version = "1.53.1" +version = "1.53.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "202caea871b69668250d242070849eb495be178ed697a3e98aebce5bc81a0bed" +checksum = "ce3335fa71841cda333a58d7615b03901380ecf09d59b3296d21f8bbac0dde4e" dependencies = [ "bytes", "libc", diff --git a/src/process_runner.rs b/src/process_runner.rs index 47f26899..28373f81 100644 --- a/src/process_runner.rs +++ b/src/process_runner.rs @@ -98,6 +98,9 @@ const TERMINATE_GRACE: Duration = Duration::from_millis(100); const EXIT_AND_DRAIN_GRACE: Duration = Duration::from_millis(500); #[cfg(target_os = "linux")] const SYSTEMD_OPERATION_GRACE: Duration = Duration::from_secs(3); +// Attachment alone may use this ceiling, always inside the original operation deadline. +#[cfg(target_os = "linux")] +const SYSTEMD_ATTACH_CEILING: Duration = Duration::from_secs(10); #[cfg(target_os = "linux")] const SYSTEMD_SLOT_WAIT: Duration = Duration::from_secs(30); // Keep both supervise admission and strict containment deterministic in the unit-test binary. @@ -2314,6 +2317,8 @@ pub struct ProcessSpec { /// extend the return past this deadline to prove that no owned process remains. On strict Linux /// runs this value also sizes the independent orphan-safety fuse. pub timeout: Option, + /// An enclosing operation may already have spent part of its budget preparing this spec. + absolute_deadline: Option, pub stdout: StreamCapture, pub stderr: StreamCapture, /// Optional nested-worker usage journal harvested after the child returns. When set, the @@ -2402,6 +2407,7 @@ impl ProcessSpec { read_only_input_snapshots: Vec::new(), pinned_direct: None, timeout: None, + absolute_deadline: None, stdout: StreamCapture::bounded(capture_limit_bytes), stderr: StreamCapture::bounded(capture_limit_bytes), nested_usage: None, @@ -2443,6 +2449,7 @@ impl ProcessSpec { read_only_input_snapshots: Vec::new(), pinned_direct: None, timeout: None, + absolute_deadline: None, stdout: StreamCapture::bounded(capture_limit_bytes), stderr: StreamCapture::bounded(capture_limit_bytes), nested_usage: None, @@ -2619,6 +2626,31 @@ impl ProcessSpec { self } + pub(crate) fn with_absolute_deadline(mut self, deadline: Instant) -> Self { + self.absolute_deadline = Some(deadline); + self + } + + fn operation_deadline(&self, started: Instant) -> Result, ProcessRunError> { + let relative = self + .timeout + .map(|timeout| { + started.checked_add(timeout).ok_or_else(|| { + setup_timeout_error( + &self.label, + &self.command_display(), + "timeout validation", + "requested duration exceeds the platform Instant range", + ) + }) + }) + .transpose()?; + Ok(match (relative, self.absolute_deadline) { + (Some(relative), Some(absolute)) => Some(relative.min(absolute)), + (relative, absolute) => relative.or(absolute), + }) + } + pub fn with_stdout(mut self, stdout: StreamCapture) -> Self { self.stdout = stdout; self @@ -3133,6 +3165,137 @@ where type ProcessStartGateCallback<'callback> = dyn for<'gate> FnMut(&ContainedProcessStartGate<'gate>) -> Result<(), String> + 'callback; +/// Bounded, static-label diagnostics only: no paths, arguments, environment or poll history. +pub(crate) struct PhaseTimings { + started: Instant, + phase_started: Instant, + phase: &'static str, + completed: [Option<(&'static str, Duration)>; 32], + count: usize, + deadline: Option, + budget: Duration, + queue_wait: Duration, + frozen: Option, +} + +impl PhaseTimings { + pub(crate) fn new( + started: Instant, + deadline: Option, + budget: Duration, + queue_wait: Duration, + phase: &'static str, + ) -> Self { + Self { + started, + phase_started: started, + phase, + completed: [None; 32], + count: 0, + deadline, + budget, + queue_wait, + frozen: None, + } + } + + pub(crate) fn enter(&mut self, phase: &'static str, now: Instant) { + if self.phase == phase { + return; + } + if let Some(slot) = self.completed.get_mut(self.count) { + *slot = Some(( + self.phase, + now.saturating_duration_since(self.phase_started), + )); + self.count += 1; + } + self.phase = phase; + self.phase_started = now; + } + + pub(crate) fn snapshot(&self, now: Instant) -> String { + if let Some(snapshot) = &self.frozen { + return snapshot.clone(); + } + use std::fmt::Write as _; + let elapsed = now.saturating_duration_since(self.phase_started); + let mut largest = (self.phase, elapsed); + let mut completed = String::new(); + for (label, duration) in self.completed.iter().flatten() { + if *duration > largest.1 { + largest = (label, *duration); + } + let _ = write!(completed, "{label}={}ms,", duration.as_millis()); + } + format!( + "phase={} phase_elapsed_ms={} admitted_elapsed_ms={} budget_ms={} remaining_ms={} queue_wait_ms={} completed=[{}] largest_phase={} largest_phase_ms={}", + self.phase, + elapsed.as_millis(), + now.saturating_duration_since(self.started).as_millis(), + self.budget.as_millis(), + self.deadline.map(|d| d.saturating_duration_since(now).as_millis()).unwrap_or(u128::MAX), + self.queue_wait.as_millis(), + completed, + largest.0, + largest.1.as_millis(), + ) + } + + pub(crate) fn freeze(&mut self, now: Instant) { + self.frozen = Some(self.snapshot(now)); + } + + fn timeout_context(&self, error: ProcessRunError) -> ProcessRunError { + match error { + ProcessRunError::SetupTimeout { + label, + command, + phase, + source, + } => { + let summary = self.snapshot(Instant::now()); + tracing::debug!(timings = %summary, "process setup deadline exhausted"); + ProcessRunError::SetupTimeout { + label, + command, + phase, + source: with_phase_diagnostics(source, summary), + } + } + other => other, + } + } +} + +#[derive(Debug)] +struct PhaseDiagnosticSource { + source: io::Error, + diagnostics: String, +} + +impl fmt::Display for PhaseDiagnosticSource { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{}; {}", self.source, self.diagnostics) + } +} + +impl std::error::Error for PhaseDiagnosticSource { + fn source(&self) -> Option<&(dyn std::error::Error + 'static)> { + Some(&self.source) + } +} + +fn with_phase_diagnostics(source: io::Error, diagnostics: String) -> io::Error { + io::Error::new( + source.kind(), + PhaseDiagnosticSource { + source, + diagnostics, + }, + ) +} + fn run_process_cancellable_with_interaction( mut spec: ProcessSpec, cancellation: &ProcessCancellation, @@ -3222,24 +3385,21 @@ fn run_process_cancellable_with_interaction( } } ensure_not_cancelled(cancellation, &spec.label, &command_display, "initial setup")?; - let operation_deadline = spec - .timeout - .map(|timeout| { - started.checked_add(timeout).ok_or_else(|| { - setup_timeout_error( - &spec.label, - &command_display, - "timeout validation", - "requested duration exceeds the platform Instant range", - ) - }) - }) - .transpose()?; + let operation_deadline = spec.operation_deadline(started)?; + let mut timings = PhaseTimings::new( + started, + operation_deadline, + operation_deadline + .map(|d| d.saturating_duration_since(started)) + .unwrap_or(Duration::MAX), + Duration::ZERO, + "preflight", + ); preflight_direct_program(&spec.command).map_err(|source| ProcessRunError::Spawn { label: spec.label.clone(), command: command_display.clone(), current_dir: spec.current_dir.clone(), - source, + source: with_phase_diagnostics(source, timings.snapshot(Instant::now())), })?; ensure_not_cancelled( cancellation, @@ -3252,7 +3412,9 @@ fn run_process_cancellable_with_interaction( &spec.label, &command_display, "preflight", - )?; + ) + .map_err(|error| timings.timeout_context(error))?; + timings.enter("io_preparation", Instant::now()); let prepared_tees = prepare_tees( &spec.label, &spec.stdout, @@ -3261,6 +3423,7 @@ fn run_process_cancellable_with_interaction( operation_deadline, &command_display, )?; + timings.enter("containment_preflight", Instant::now()); let mut prepared_process_tree = PreparedProcessTree::prepare( spec.containment, &spec.side_effects, @@ -3268,7 +3431,9 @@ fn run_process_cancellable_with_interaction( &command_display, operation_deadline, cancellation, + &mut timings, )?; + timings.enter("native_preparation", Instant::now()); if let Err(source) = prepared_process_tree.prepare_native_entry(&spec, operation_deadline, cancellation) { @@ -3284,24 +3449,31 @@ fn run_process_cancellable_with_interaction( &spec.label, &command_display, "sealed native preparation", - )?; + ) + .map_err(|error| timings.timeout_context(error))?; return Err(containment_setup_error( spec.label.clone(), command_display.clone(), - source, + with_phase_diagnostics(source, timings.snapshot(Instant::now())), )); } + timings.enter("command_build", Instant::now()); let mut command = prepared_process_tree .build_command(&spec) .map_err(|source| { - containment_setup_error(spec.label.clone(), command_display.clone(), source) + containment_setup_error( + spec.label.clone(), + command_display.clone(), + with_phase_diagnostics(source, timings.snapshot(Instant::now())), + ) })?; ensure_setup_budget( operation_deadline, &spec.label, &command_display, "containment and I/O setup", - )?; + ) + .map_err(|error| timings.timeout_context(error))?; prepared_process_tree .configure_stdin(&mut command, &spec.stdin) .map_err(|source| { @@ -3313,7 +3485,8 @@ fn run_process_cancellable_with_interaction( &spec.label, &command_display, "stdin relay setup", - )?; + ) + .map_err(|error| timings.timeout_context(error))?; ensure_not_cancelled( cancellation, &spec.label, @@ -3334,11 +3507,19 @@ fn run_process_cancellable_with_interaction( source: std::io::Error::other("synthetic child spawn failure"), }); } + timings.enter("spawn", Instant::now()); + ensure_setup_budget( + operation_deadline, + &spec.label, + &command_display, + "child spawn gate", + ) + .map_err(|error| timings.timeout_context(error))?; let mut child = command.spawn().map_err(|source| ProcessRunError::Spawn { label: spec.label.clone(), command: command_display.clone(), current_dir: spec.current_dir.clone(), - source, + source: with_phase_diagnostics(source, timings.snapshot(Instant::now())), })?; #[cfg(test)] if let Some(marker) = env::var_os("MACO_TEST_AFTER_CHILD_SPAWN_MARKER") { @@ -3361,6 +3542,7 @@ fn run_process_cancellable_with_interaction( &command_display, operation_deadline, cancellation, + &mut timings, ) { Ok(process_tree) => process_tree, Err(error) => { @@ -3663,6 +3845,9 @@ fn run_process_cancellable_with_interaction( let output_backlog = output_drainers.drain_ready(); input_writer.drain_ready(); + #[cfg(test)] + let test_observed_at = PROCESS_WAIT_TEST_HOOK + .with(|hook| hook.borrow_mut().as_mut().map(|hook| hook(&mut child))); if status.is_none() { status = match child.try_wait() { Ok(status) => status, @@ -3684,11 +3869,14 @@ fn run_process_cancellable_with_interaction( }; } + let observed_at = Instant::now(); + #[cfg(test)] + let observed_at = test_observed_at.unwrap_or(observed_at); let loop_decision = process_loop_decision( status.is_some(), cancellation.is_cancelled(), operation_deadline, - Instant::now(), + observed_at, ); if loop_decision == ProcessLoopDecision::Cancel { @@ -3872,6 +4060,14 @@ fn run_process_cancellable_with_interaction( }) } +#[cfg(test)] +type ProcessWaitTestHook = Box Instant>; + +#[cfg(test)] +thread_local! { + static PROCESS_WAIT_TEST_HOOK: std::cell::RefCell> = const { std::cell::RefCell::new(None) }; +} + #[derive(Debug, Clone, Copy, PartialEq, Eq)] enum ProcessLoopDecision { Cancel, @@ -4778,10 +4974,22 @@ fn process_ownership_error( fn environment_failure_from_source(source: &std::io::Error) -> Option<(EnvironmentFailure, bool)> { #[cfg(target_os = "linux")] { - source - .get_ref() - .and_then(|source| source.downcast_ref::()) - .map(|source| (source.failure.clone(), source.target_process_started)) + let mut current = source; + let mut diagnostics = Vec::new(); + loop { + let inner = current.get_ref()?; + if let Some(failure) = inner.downcast_ref::() { + let mut value = failure.failure.clone(); + for context in diagnostics { + value.summary.push_str("; "); + value.summary.push_str(context); + } + return Some((value, failure.target_process_started)); + } + let context = inner.downcast_ref::()?; + diagnostics.push(context.diagnostics.as_str()); + current = &context.source; + } } #[cfg(not(target_os = "linux"))] { diff --git a/src/process_runner/part2.rs b/src/process_runner/part2.rs index d1da42c4..78183b26 100644 --- a/src/process_runner/part2.rs +++ b/src/process_runner/part2.rs @@ -715,7 +715,10 @@ impl PreparedProcessTree { command: &str, operation_deadline: Option, cancellation: &ProcessCancellation, + timings: &mut PhaseTimings, ) -> Result { + #[cfg(not(target_os = "linux"))] + let _ = &timings; let unavailable = |source| ProcessRunError::ContainmentUnavailable { label: label.to_string(), command: command.to_string(), @@ -754,7 +757,7 @@ impl PreparedProcessTree { ReviewedRequiredContainmentBackend::LinuxSystemdCgroupV2 => { #[cfg(target_os = "linux")] { - match SystemdUnit::prepare(operation_deadline, cancellation) { + match SystemdUnit::prepare(operation_deadline, cancellation, timings) { Ok(unit) => Ok(Self { backend: PreparedContainmentBackend::Systemd(Box::new(unit)), side_effects, @@ -775,13 +778,13 @@ impl PreparedProcessTree { label, command, "strict containment slot acquisition", - source.to_string(), + format!("{source}; {}", timings.snapshot(Instant::now())), )) } Err(source) => Err(containment_setup_error( label.to_string(), command.to_string(), - source, + with_phase_diagnostics(source, timings.snapshot(Instant::now())), )), } } @@ -893,18 +896,31 @@ impl PreparedProcessTree { command: &str, operation_deadline: Option, cancellation: &ProcessCancellation, + timings: &mut PhaseTimings, ) -> Result { + #[cfg(not(target_os = "linux"))] + let _ = &timings; match self.backend { #[cfg(target_os = "linux")] PreparedContainmentBackend::Systemd(mut unit) => { unit.launcher_spawned = true; - if let Err(source) = unit.confirm_attached(child, operation_deadline, cancellation) + if let Err(source) = unit.confirm_attached_timed(child, operation_deadline, cancellation, timings) { + // Only the wrapper's fixed phase/gate diagnostics are safe to expose. + // Its underlying source may contain launcher output or FIFO paths. + let cancellation_diagnostics = source.get_ref() + .and_then(|source| source.downcast_ref::()) + .map(|source| source.diagnostics.clone()) + .unwrap_or_else(|| timings.snapshot(Instant::now())); + let rollback_started = Instant::now(); if let Err(error) = unit.rollback_startup(label) { fail_closed_stuck_owner(&format!( "{label} systemd containment startup rollback: {error}" )); } + let rollback_elapsed = rollback_started.elapsed(); + tracing::debug!(elapsed_ms = rollback_elapsed.as_millis(), "systemd attachment rollback verified empty"); + let source = with_phase_diagnostics(source, format!("attachment rollback: elapsed_ms={} completed=true", rollback_elapsed.as_millis())); return if cancellation.is_cancelled() { Err(ProcessRunError::Cancelled { label: label.to_string(), @@ -918,7 +934,7 @@ impl PreparedProcessTree { ), side_effects: self.side_effects, process_error: Some(format!( - "{label} was cancelled by its run supervisor" + "process was cancelled by its run supervisor; {cancellation_diagnostics}" )), stdin_error: None, })), diff --git a/src/process_runner/part3.rs b/src/process_runner/part3.rs index 90a8c185..e34cf0fc 100644 --- a/src/process_runner/part3.rs +++ b/src/process_runner/part3.rs @@ -396,6 +396,7 @@ impl SystemdUnit { fn prepare( operation_deadline: Option, cancellation: &ProcessCancellation, + timings: &mut PhaseTimings, ) -> std::io::Result { #[cfg(test)] if env::var_os("MACO_TEST_DISABLE_STRICT_CONTAINMENT").is_some() { @@ -405,7 +406,9 @@ impl SystemdUnit { )); } let client_runtime = trusted_linux_runtime_root()?; + timings.enter("permit_wait", Instant::now()); let permit = SystemdUnitPermit::acquire(&client_runtime, operation_deadline, cancellation)?; + timings.enter("containment_preparation", Instant::now()); let systemd_run = find_trusted_unix_executable( "systemd-run", &[ @@ -943,29 +946,45 @@ impl SystemdUnit { Ok(()) } + #[cfg(test)] fn confirm_attached( &mut self, child: &mut Child, operation_deadline: Option, cancellation: &ProcessCancellation, ) -> std::io::Result<()> { - let result = self.confirm_attached_inner(child, operation_deadline, cancellation); - match result { - Err(source) - if matches!( - source.kind(), - io::ErrorKind::TimedOut | io::ErrorKind::Interrupted - ) => - { - // Observe before attach() rolls back the unit and removes its gate files. - let diagnostics = self.start_gate_diagnostics(child); - Err(io::Error::new( - source.kind(), - format!("{source}; {diagnostics}"), - )) - } - other => other, - } + let now = Instant::now(); + let mut timings = PhaseTimings::new(now, operation_deadline, operation_deadline.map(|d| d.saturating_duration_since(now)).unwrap_or(SYSTEMD_OPERATION_GRACE), Duration::ZERO, "attachment"); + self.confirm_attached_timed(child, operation_deadline, cancellation, &mut timings) + } + + fn confirm_attached_timed( + &mut self, + child: &mut Child, + operation_deadline: Option, + cancellation: &ProcessCancellation, + timings: &mut PhaseTimings, + ) -> std::io::Result<()> { + #[cfg(test)] + run_attach_test_hook("attach_deadline_selected"); + let now = attach_now(); + timings.enter("ownership_observation", now); + let deadline = systemd_attach_deadline(now, operation_deadline); + let allowance = deadline.as_ref().map(|d| d.saturating_duration_since(now).as_millis()).unwrap_or(0); + let result = if cancellation.is_cancelled() { + check_attach_budget(now, cancellation) + } else { match deadline { + Ok(deadline) => self.confirm_attached_inner(child, deadline, cancellation, timings), + Err(source) => Err(source), + }}; + // Freeze timings before diagnostics and attach() rollback remove the gate evidence. + let observed = attach_now(); + let summary = format!("{} attach_allowance_ms={} operation_remaining_ms={}", timings.snapshot(observed), allowance, operation_deadline.map(|d| d.saturating_duration_since(observed).as_millis()).unwrap_or(u128::MAX)); + tracing::debug!(timings = %summary, completed = result.is_ok(), "systemd attachment finished before cleanup"); + result.map_err(|source| { + let diagnostics = format!("systemd transient unit {}; {}", self.name, self.start_gate_diagnostics(child)); + with_phase_diagnostics(source, format!("{summary}; {diagnostics}")) + }) } fn start_gate_diagnostics(&self, child: &mut Child) -> String { @@ -1077,29 +1096,18 @@ impl SystemdUnit { fn confirm_attached_inner( &mut self, child: &mut Child, - operation_deadline: Option, + deadline: Instant, cancellation: &ProcessCancellation, + timings: &mut PhaseTimings, ) -> std::io::Result<()> { - let deadline = bounded_operation_deadline(SYSTEMD_OPERATION_GRACE, operation_deadline)?; loop { - if cancellation.is_cancelled() { - return Err(std::io::Error::new( - std::io::ErrorKind::Interrupted, - "systemd containment attachment was cancelled", - )); - } - if Instant::now() >= deadline { - return Err(std::io::Error::new( - std::io::ErrorKind::TimedOut, - format!( - "systemd transient unit {} did not reach its start gate before the bounded setup deadline", - self.name - ), - )); - } + self.check_attach_launcher_budget(child, deadline, cancellation)?; if matches!(cgroup_populated(&self.cgroup_path)?, Some(true)) { self.observed_owned = true; } + if self.observed_owned && !self.fifos_prepared { + timings.enter("fifo_preparation", Instant::now()); + } if !self.fifos_prepared && self.fifo_waiting_path.is_file() { prepare_systemd_gate_fifos( &self.runtime_dir, @@ -1111,11 +1119,16 @@ impl SystemdUnit { ], )?; self.fifos_prepared = true; + timings.enter(if self.observed_owned { "owner_channel" } else { "ownership_observation" }, Instant::now()); } if self.observed_owned && self.owner_channel.is_none() && self.owner_fifo_path.exists() { + timings.enter("owner_channel", Instant::now()); match open_systemd_owner_fifo(&self.owner_fifo_path) { - Ok(channel) => self.owner_channel = Some(channel), + Ok(channel) => { + self.owner_channel = Some(channel); + timings.enter("guardian_wait", Instant::now()); + } Err(error) if error.raw_os_error() == Some(libc::ENOENT) => {} Err(error) => return Err(error), } @@ -1124,6 +1137,7 @@ impl SystemdUnit { && self.waiting_path.is_file() && !self.environment_published { + timings.enter("environment_publication", Instant::now()); for private_file in std::mem::take(&mut self.pending_runtime_files) { let path = match private_file.destination { PrivateRuntimeFileDestination::RuntimeDirectory => { @@ -1157,15 +1171,23 @@ impl SystemdUnit { } } if self.environment_published && !self.environment_released { + self.check_attach_launcher_budget(child, deadline, cancellation)?; + timings.enter("environment_release", Instant::now()); match signal_systemd_fifo(&self.environment_fifo_path, b"environment\n") { - Ok(()) => self.environment_released = true, + Ok(()) => { + self.environment_released = true; + timings.enter("ready_wait", Instant::now()); + } Err(error) if error.raw_os_error() == Some(libc::ENXIO) => {} Err(error) => return Err(error), } } + self.check_attach_launcher_budget(child, deadline, cancellation)?; if self.environment_released && self.ready_path.is_file() { if self.sandbox.is_some() && !self.sandbox_verified { - self.verify_effective_sandbox()?; + timings.enter("sandbox_verification", Instant::now()); + self.verify_effective_sandbox(deadline, cancellation)?; + attach_checkpoint("after_sandbox_verification", deadline, cancellation)?; self.sandbox_verified = true; // Only this successful native verification can issue pending proof. self.pending_read_only = self.prepared_read_only.take().map(|prepared| { @@ -1182,6 +1204,7 @@ impl SystemdUnit { if env::var_os("MACO_TEST_ABORT_BEFORE_START_RELEASE").is_some() { std::process::abort(); } + attach_checkpoint("before_attachment_success", deadline, cancellation)?; return Ok(()); } if let Some(status) = child.try_wait()? { @@ -1198,6 +1221,30 @@ impl SystemdUnit { } } + fn check_attach_launcher_budget( + &mut self, + child: &mut Child, + deadline: Instant, + cancellation: &ProcessCancellation, + ) -> io::Result<()> { + #[cfg(test)] + run_attach_test_hook("before_attach_budget_check"); + if let Err(error) = check_attach_budget(deadline, cancellation) { + if let Some(status) = child.try_wait()? { + self.launcher_completed = true; + let output = collect_exited_child_startup_output(child); + return Err(systemd_launcher_exit_error( + status, + &output, + self.target_program_path.as_deref(), + "before transient-unit attachment completed", + )); + } + return Err(error); + } + Ok(()) + } + fn side_effect_evidence(&self) -> SideEffectConfinementEvidence { match &self.sandbox { Some(sandbox) if self.sandbox_verified => { @@ -1210,24 +1257,29 @@ impl SystemdUnit { } } - fn verify_effective_sandbox(&self) -> std::io::Result<()> { + fn verify_effective_sandbox(&self, deadline: Instant, cancellation: &ProcessCancellation) -> std::io::Result<()> { + check_attach_budget(deadline, cancellation)?; let sandbox = self.sandbox.as_ref().ok_or_else(|| { std::io::Error::other("strict sandbox verification omitted requested profile") })?; sandbox.verify_path_identities()?; verify_sandbox_mount_report(&self.sandbox_report_path, &sandbox.mount_checks)?; + attach_checkpoint("before_sandbox_property_probe", deadline, cancellation)?; let properties = systemd_show_properties( &self.systemctl, &self.client_runtime, &self.name, SYSTEMD_SANDBOX_SHOW_PROPERTIES, + deadline, + cancellation, )?; verify_systemd_sandbox_properties( sandbox, &properties, &self.runtime_dir, self.isolated_root.as_ref().map(tempfile::TempDir::path), - ) + )?; + check_attach_budget(deadline, cancellation) } fn release_start_gate( @@ -1657,6 +1709,8 @@ fn systemd_show_properties( client_runtime: &Path, unit: &str, names: &[&str], + deadline: Instant, + cancellation: &ProcessCancellation, ) -> std::io::Result> { let mut args = vec![ OsString::from("--user"), @@ -1669,11 +1723,13 @@ fn systemd_show_properties( .map(|name| OsString::from(format!("--property={name}"))), ); args.push(OsString::from(unit)); - let (status, stdout, stderr) = run_control_command_capture_bounded( + let (status, stdout, stderr) = run_control_command_capture_bounded_until( systemctl, &args, "systemctl sandbox verification", client_runtime, + Some(deadline), + cancellation, )?; if !status.success() { return Err(std::io::Error::other(format!( @@ -1698,18 +1754,36 @@ fn systemd_show_properties( .filter_map(|line| line.split_once('=')) .map(|(name, value)| (name.to_string(), value.to_string())) .collect::>(); + check_attach_budget(deadline, cancellation)?; Ok(properties) } -#[cfg(target_os = "linux")] +#[cfg(all(test, target_os = "linux"))] fn run_control_command_capture_bounded( program: &Path, args: &[OsString], label: &str, client_runtime: &Path, +) -> std::io::Result<(ExitStatus, CapturedBytes, CapturedBytes)> { + run_control_command_capture_bounded_until(program, args, label, client_runtime, None, &ProcessCancellation::new()) +} + +#[cfg(target_os = "linux")] +fn run_control_command_capture_bounded_until( + program: &Path, + args: &[OsString], + label: &str, + client_runtime: &Path, + operation_deadline: Option, + cancellation: &ProcessCancellation, ) -> std::io::Result<(ExitStatus, CapturedBytes, CapturedBytes)> { use std::os::unix::process::CommandExt; + if cancellation.is_cancelled() { + return Err(io::Error::new(io::ErrorKind::Interrupted, "systemd sandbox property probe was cancelled")); + } + let deadline = bounded_operation_deadline(SYSTEMD_OPERATION_GRACE, operation_deadline)?; + check_attach_budget(deadline, cancellation)?; let mut command = Command::new(program); command .env_clear() @@ -1719,6 +1793,7 @@ fn run_control_command_capture_bounded( .stdout(Stdio::piped()) .stderr(Stdio::piped()) .process_group(0); + check_attach_budget(deadline, cancellation)?; let mut child = command.spawn()?; let stdout = child .stdout @@ -1732,22 +1807,29 @@ fn run_control_command_capture_bounded( configure_cancellable_io(&stderr)?; let mut drainers = OutputDrainers::start(stdout, stderr, label, 64 * 1024, 64 * 1024, None, None); - let deadline = Instant::now() + SYSTEMD_OPERATION_GRACE; let status = loop { let backlog = drainers.drain_ready(); - if let Some(status) = child.try_wait()? { - break status; - } - if Instant::now() >= deadline { + let status = child.try_wait()?; + #[cfg(test)] + run_attach_test_hook("before_control_budget_check"); + if let Err(error) = check_attach_budget(deadline, cancellation) { + if status.is_some() { + let _ = finish_output_drainers_after_exit(&mut drainers, EXIT_AND_DRAIN_GRACE); + let _ = drainers.cancel_incomplete(label); + return Err(error); + } let cleanup = terminate_unix_process_group(&mut child, false, label); let status = wait_for_exit_until(&mut child, Instant::now() + SYSTEMD_OPERATION_GRACE)? .unwrap_or_else(|| fail_closed_stuck_owner(label)); let detail = cleanup.unwrap_or_else(|| { - format!("{label} exceeded its bounded deadline and was terminated with {status}") + format!("{label} control rollback completed with {status}") }); let _ = finish_output_drainers_after_exit(&mut drainers, EXIT_AND_DRAIN_GRACE); let _ = drainers.cancel_incomplete(label); - return Err(std::io::Error::new(std::io::ErrorKind::TimedOut, detail)); + return Err(with_phase_diagnostics(error, detail)); + } + if let Some(status) = status { + break status; } if !backlog { thread::sleep(POLL_INTERVAL); @@ -1763,6 +1845,7 @@ fn run_control_command_capture_bounded( if let Some(error) = output_error { return Err(std::io::Error::other(error)); } + attach_checkpoint("before_control_success", deadline, cancellation)?; Ok((status, stdout, stderr)) } @@ -2287,6 +2370,64 @@ fn enforce_total_operation_deadline(operation_deadline: Option) -> std: Ok(()) } +#[cfg(target_os = "linux")] +fn systemd_attach_deadline(now: Instant, operation_deadline: Option) -> io::Result { + let allowance = match operation_deadline { + Some(deadline) => { + let remaining = deadline.checked_duration_since(now).filter(|r| !r.is_zero()).ok_or_else(|| io::Error::new(io::ErrorKind::TimedOut, "systemd attachment operation deadline is exhausted"))?; + remaining.min(SYSTEMD_OPERATION_GRACE.max(SYSTEMD_ATTACH_CEILING.min(remaining / 2))) + } + None => SYSTEMD_OPERATION_GRACE, + }; + clamp_platform_operation_deadline(now, allowance, operation_deadline) +} + +#[cfg(target_os = "linux")] +fn check_attach_budget(deadline: Instant, cancellation: &ProcessCancellation) -> io::Result<()> { + if cancellation.is_cancelled() { + return Err(io::Error::new(io::ErrorKind::Interrupted, "systemd containment attachment was cancelled")); + } + if attach_now() >= deadline { + return Err(io::Error::new(io::ErrorKind::TimedOut, "systemd transient unit did not reach its start gate before the bounded setup deadline")); + } + Ok(()) +} + +#[cfg(target_os = "linux")] +fn attach_now() -> Instant { + #[cfg(test)] + if let Some(now) = ATTACH_TEST_NOW.with(|clock| clock.get()) { + return now; + } + Instant::now() +} + +#[cfg(target_os = "linux")] +fn attach_checkpoint(phase: &'static str, deadline: Instant, cancellation: &ProcessCancellation) -> io::Result<()> { + #[cfg(test)] + run_attach_test_hook(phase); + let _ = phase; + check_attach_budget(deadline, cancellation) +} + +#[cfg(all(test, target_os = "linux"))] +fn run_attach_test_hook(phase: &'static str) { + ATTACH_TEST_HOOK.with(|hook| { + if let Some(hook) = hook.borrow_mut().as_mut() { + hook(phase); + } + }); +} + +#[cfg(all(test, target_os = "linux"))] +type AttachTestHook = Box; + +#[cfg(all(test, target_os = "linux"))] +thread_local! { + static ATTACH_TEST_NOW: std::cell::Cell> = const { std::cell::Cell::new(None) }; + static ATTACH_TEST_HOOK: std::cell::RefCell> = const { std::cell::RefCell::new(None) }; +} + #[cfg(target_os = "linux")] fn bounded_operation_deadline( platform_grace: Duration, @@ -4011,6 +4152,28 @@ mod start_gate_deadline_phase_tests { use super::*; use std::time::{Duration, Instant}; + #[test] + fn adaptive_attach_budget_scales_and_clips_without_renewal() { + let now = Instant::now(); + for (remaining, expected) in [(40, 10), (12, 6), (6, 3), (1, 1)] { + let operation = now + Duration::from_secs(remaining); + let deadline = systemd_attach_deadline(now, Some(operation)).unwrap(); + assert_eq!(deadline, now + Duration::from_secs(expected)); + for poll in 0..expected { + let observed = now + Duration::from_secs(poll); + // The selected deadline is retained by confirm_attached_inner, never recomputed. + assert!(observed < deadline && deadline <= operation); + } + } + for expired in [now, now - Duration::from_nanos(1)] { + assert_eq!(systemd_attach_deadline(now, Some(expired)).unwrap_err().kind(), io::ErrorKind::TimedOut); + } + assert_eq!(systemd_attach_deadline(now, None).unwrap(), now + SYSTEMD_OPERATION_GRACE); + if let Some(large) = now.checked_add(Duration::from_secs(u32::MAX as u64)) { + assert_eq!(systemd_attach_deadline(large, Some(large + Duration::from_secs(12))).unwrap(), large + Duration::from_secs(6)); + } + } + #[test] fn platform_start_gate_grace_is_clamped_from_the_supplied_now() { let now = Instant::now(); diff --git a/src/process_runner/tests.rs b/src/process_runner/tests.rs index ea0fa1bb..b5280b10 100644 --- a/src/process_runner/tests.rs +++ b/src/process_runner/tests.rs @@ -3249,6 +3249,16 @@ fn systemd_start_gate_timeout_preserves_bounded_redacted_diagnostics_before_clea "{message}" ); assert!(message.contains("pre-cleanup gate: owned=true fifo_waiting=true fifos_prepared=true owner_channel=true guardian_waiting=true environment_published=true environment_released=true ready=false sandbox_verified=false"), "{message}"); + for timing in [ + "phase=", + "phase_elapsed_ms=", + "completed=[", + "attach_allowance_ms=", + "operation_remaining_ms=", + ] { + assert!(message.contains(timing), "{message}"); + } + assert!(message.contains("operation_remaining_ms=0"), "{message}"); assert!( message.contains("maco containment guardian: could not inspect sandbox mount"), "{message}" @@ -5720,6 +5730,582 @@ fn required_containment_unavailable_refuses_before_spawn() { assert!(!marker.exists()); } +#[cfg(target_os = "linux")] +#[test] +fn phase_diagnostics_preserve_typed_environment_and_io_causes() { + let source = environment_failure_io( + EnvironmentFailure::sandbox_unavailable("fixture namespace refusal".to_string()), + false, + ); + let wrapped = with_phase_diagnostics( + with_phase_diagnostics(source, "phase=sandbox_verification".to_string()), + "attachment rollback: completed=true".to_string(), + ); + let error = process_ownership_error("typed fixture".to_string(), "true".to_string(), wrapped); + match error { + ProcessRunError::EnvironmentFailure { + failure, + target_process_started, + .. + } => { + assert!(!target_process_started); + assert!(failure.summary.contains("fixture namespace refusal")); + assert!(failure.summary.contains("phase=sandbox_verification")); + assert!(failure + .summary + .contains("attachment rollback: completed=true")); + } + other => panic!("typed environment classification lost: {other:?}"), + } + let wrapped = with_phase_diagnostics( + io::Error::from_raw_os_error(libc::EACCES), + "phase=fifo_preparation".to_string(), + ); + assert_eq!(wrapped.kind(), io::ErrorKind::PermissionDenied); + let inner = wrapped + .get_ref() + .unwrap() + .downcast_ref::() + .unwrap(); + assert_eq!(inner.source.raw_os_error(), Some(libc::EACCES)); +} + +#[cfg(target_os = "linux")] +#[test] +fn systemd_attach_budget_failure_preserves_exited_launcher_status() { + let _guard = AttachTestGuard; + let temp = tempfile::tempdir().unwrap(); + let mut unit = systemd_unit_fixture(temp.path(), None); + let mut child = Command::new("/bin/sh") + .args(["-c", "printf launcher-failure >&2; exit 17"]) + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + assert_eq!(child.wait().unwrap().code(), Some(17)); + let now = Instant::now(); + ATTACH_TEST_NOW.with(|clock| clock.set(Some(now))); + let mut timings = + PhaseTimings::new(now, Some(now), Duration::ZERO, Duration::ZERO, "attachment"); + let error = unit + .confirm_attached_inner(&mut child, now, &ProcessCancellation::new(), &mut timings) + .unwrap_err(); + assert!(unit.launcher_completed); + assert!(error.to_string().contains("17"), "{error}"); + assert!(error.to_string().contains("launcher-failure"), "{error}"); +} + +#[cfg(target_os = "linux")] +#[test] +fn systemd_attach_cancellation_redacts_launcher_failure_and_rolls_back() { + let _guard = AttachTestGuard; + let temp = tempfile::tempdir().unwrap(); + let mut unit = systemd_unit_fixture(temp.path(), None); + unit.cgroup_path = temp.path().join("absent-cgroup"); + unit.target_program_path = Some(PathBuf::from("/private/SECRET-program")); + let marker = temp.path().join("rollback-marker"); + fs::write(&marker, b"private").unwrap(); + unit.runtime_file_paths.push(marker.clone()); + let mut child = Command::new("/bin/sh") + .args([ + "-c", + "printf SECRET-stdout; printf SECRET-stderr >&2; exit 17", + ]) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + child.wait().unwrap(); + let cancellation = ProcessCancellation::new(); + let signal = cancellation.clone(); + ATTACH_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase == "before_attach_budget_check" { + signal.cancel(); + } + })); + }); + let prepared = PreparedProcessTree { + backend: PreparedContainmentBackend::Systemd(Box::new(unit)), + side_effects: SideEffectConfinementEvidence::Unverified( + SideEffectConfinementProfileKind::StrictOfflineWorkspace, + ), + }; + let now = Instant::now(); + let mut timings = PhaseTimings::new( + now, + None, + SYSTEMD_OPERATION_GRACE, + Duration::ZERO, + "attachment", + ); + let error = prepared + .attach( + &mut child, + "cancel fixture", + "redacted command", + None, + &cancellation, + &mut timings, + ) + .err() + .expect("attachment must be cancelled"); + let evidence = error.cancellation_evidence().unwrap(); + assert!(evidence.process_tree.is_verified_empty()); + let message = evidence.process_error.as_ref().unwrap(); + assert!(message.contains("was cancelled by its run supervisor")); + assert!( + message.contains("phase=") && message.contains("pre-cleanup gate:"), + "{message}" + ); + assert!( + !message.contains("SECRET") && !message.contains("/private"), + "{message}" + ); + assert!( + !marker.exists(), + "real attachment rollback removes private files" + ); +} + +#[cfg(target_os = "linux")] +#[test] +fn sandbox_property_probe_never_signals_reaped_leader_group() { + use std::os::unix::process::CommandExt; + let _guard = AttachTestGuard; + let temp = tempfile::tempdir().unwrap(); + let pid_file = temp.path().join("leader"); + let release = temp.path().join("release"); + let witness = std::rc::Rc::new(std::cell::RefCell::new(None::)); + let observed_witness = witness.clone(); + let now = Instant::now(); + ATTACH_TEST_NOW.with(|clock| clock.set(Some(now))); + let observed_pid_file = pid_file.clone(); + let observed_release = release.clone(); + ATTACH_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase != "before_control_budget_check" || !observed_pid_file.exists() { + return; + } + let Some(pid) = fs::read_to_string(&observed_pid_file) + .ok() + .and_then(|pid| pid.trim().parse::().ok()) + else { + return; + }; + if observed_witness.borrow().is_none() { + let child = Command::new("/bin/sleep") + .arg("30") + .process_group(pid) + .spawn() + .unwrap(); + *observed_witness.borrow_mut() = Some(child); + fs::write(&observed_release, b"release").unwrap(); + } else if !Path::new(&format!("/proc/{pid}")).exists() { + // try_wait has reaped the leader. Its still-live group must not be signalled. + ATTACH_TEST_NOW + .with(|clock| clock.set(Some(Instant::now() + Duration::from_secs(30)))); + } + })); + }); + let args = [ + OsString::from("-c"), + OsString::from(format!( + "echo $$ > '{}'; while [ ! -f '{}' ]; do /bin/sleep 0.01; done", + pid_file.display(), + release.display() + )), + ]; + let result = run_control_command_capture_bounded_until( + Path::new("/bin/sh"), + &args, + "reaped leader", + temp.path(), + None, + &ProcessCancellation::new(), + ); + let mut witness = witness + .borrow_mut() + .take() + .expect("same-group witness started"); + let witness_status = witness.try_wait().unwrap(); + if witness_status.is_none() { + witness.kill().unwrap(); + } + witness.wait().unwrap(); + assert_eq!(result.unwrap_err().kind(), io::ErrorKind::TimedOut); + assert!( + witness_status.is_none(), + "reaped leader's group was signalled" + ); +} + +#[cfg(target_os = "linux")] +#[test] +fn bounded_git_absolute_deadline_caps_relative_command_timeout() { + let temp = tempfile::tempdir().unwrap(); + let marker = temp.path().join("must-not-run"); + let now = Instant::now(); + let base = ProcessSpec::shell( + "absolute status budget", + Shell::UnixSh, + format!("touch '{}'", marker.display()), + temp.path(), + 128, + ) + .with_timeout(Some(Duration::from_secs(40))); + assert_eq!(base.absolute_deadline, None); + assert_eq!( + ProcessSpec::direct( + "direct default", + "/bin/true", + [] as [&str; 0], + temp.path(), + 128 + ) + .absolute_deadline, + None + ); + let clipped = base + .clone() + .with_absolute_deadline(now + Duration::from_secs(12)); + assert_eq!( + clipped.operation_deadline(now).unwrap(), + Some(now + Duration::from_secs(12)) + ); + // Spec preparation cannot renew the enclosing deadline. + assert_eq!( + clipped + .operation_deadline(now + Duration::from_secs(5)) + .unwrap(), + Some(now + Duration::from_secs(12)) + ); + assert_eq!( + base.clone() + .with_absolute_deadline(now + Duration::from_secs(60)) + .operation_deadline(now) + .unwrap(), + Some(now + Duration::from_secs(40)) + ); + assert!(matches!( + base.clone() + .with_timeout(Some(Duration::MAX)) + .with_absolute_deadline(now) + .operation_deadline(now), + Err(ProcessRunError::SetupTimeout { .. }) + )); + let expired = base.with_absolute_deadline(now); + let error = run_process(expired).unwrap_err(); + assert!(matches!(error, ProcessRunError::SetupTimeout { .. })); + assert!(error.to_string().contains("phase=preflight")); + assert!(!marker.exists()); + // Exercise an actual exit first observed after the absolute deadline. + let _guard = AttachTestGuard; + let deadline = Instant::now() + Duration::from_secs(60); + PROCESS_WAIT_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |child| { + assert!(child.wait().unwrap().success()); + deadline + Duration::from_secs(1) + })); + }); + let output = run_process( + ProcessSpec::direct("late true", "/bin/true", [] as [&str; 0], temp.path(), 128) + .with_containment(ContainmentPolicy::TrustedBestEffort) + .with_absolute_deadline(deadline), + ) + .unwrap(); + assert!( + output.status.unwrap().success(), + "the real child exited successfully" + ); + assert!(output.timed_out, "a late observation must still time out"); + assert!(!output.safety_sensitive_succeeded()); +} + +#[cfg(target_os = "linux")] +struct AttachTestGuard; + +#[cfg(target_os = "linux")] +impl Drop for AttachTestGuard { + fn drop(&mut self) { + ATTACH_TEST_NOW.with(|clock| clock.set(None)); + ATTACH_TEST_HOOK.with(|hook| hook.borrow_mut().take()); + PROCESS_WAIT_TEST_HOOK.with(|hook| hook.borrow_mut().take()); + } +} + +#[cfg(target_os = "linux")] +#[test] +fn systemd_attach_delayed_ready_retains_full_ownership_and_sandbox_proof() { + let _guard = AttachTestGuard; + let temp = tempfile::tempdir().unwrap(); + let marker = temp.path().join("target-ran"); + let advanced = std::rc::Rc::new(std::cell::Cell::new(false)); + let observed = advanced.clone(); + let mut selected_at = None; + ATTACH_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase == "attach_deadline_selected" { + let base = attach_now(); + selected_at = Some(base); + ATTACH_TEST_NOW.with(|clock| clock.set(Some(base))); + } else if phase == "after_sandbox_verification" { + observed.set(true); + let base = selected_at.expect("capture the deadline-selection clock"); + ATTACH_TEST_NOW.with(|clock| clock.set(Some(base + Duration::from_secs(4)))); + } + })) + }); + let capture = TestSystemdUnitNameCapture::start(); + let output = run_process( + ProcessSpec::shell( + "delayed attach proof", + Shell::UnixSh, + format!("touch '{}'", marker.display()), + temp.path(), + 128, + ) + .with_timeout(Some(Duration::from_secs(12))), + ) + .expect("strict production path must pass with four-second injected readiness"); + assert!(advanced.get(), "must reach real sandbox verification"); + assert!(output.status.unwrap().success() && !output.timed_out); + assert!(output.safety_evidence_verified(), "{output:?}"); + assert!(marker.exists()); + assert_systemd_units_have_no_residue(&capture.finish()); + ATTACH_TEST_NOW.with(|clock| clock.set(None)); + ATTACH_TEST_HOOK.with(|hook| hook.borrow_mut().take()); + + // Ready flags alone are insufficient: a missing mount report still refuses attachment. + let runtime = temp.path().join("fixture"); + fs::create_dir(&runtime).unwrap(); + let mut unit = systemd_unit_fixture(&runtime, None); + let spec = ProcessSpec::shell( + "missing sandbox proof", + Shell::UnixSh, + ":", + temp.path(), + 128, + ); + unit.build_command(&spec).unwrap(); + unit.observed_owned = true; + unit.fifos_prepared = true; + unit.owner_channel = Some(tempfile::tempfile().unwrap()); + unit.environment_published = true; + unit.environment_released = true; + fs::write(&unit.ready_path, b"").unwrap(); + let mut child = Command::new("/bin/sleep") + .arg("30") + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + let result = unit.confirm_attached( + &mut child, + Some(Instant::now() + Duration::from_secs(12)), + &ProcessCancellation::new(), + ); + child.kill().unwrap(); + child.wait().unwrap(); + assert!(result.is_err() && !unit.sandbox_verified); +} + +#[cfg(target_os = "linux")] +#[test] +fn systemd_attach_cancel_or_expire_after_verification_never_releases_target() { + for checkpoint in [ + "before_sandbox_property_probe", + "after_sandbox_verification", + "before_attachment_success", + ] { + for cancel in [false, true] { + let _guard = AttachTestGuard; + let temp = tempfile::tempdir().unwrap(); + let marker = temp.path().join("must-not-run"); + let cancellation = ProcessCancellation::new(); + let observed_cancel = cancellation.clone(); + let reached = std::rc::Rc::new(std::cell::Cell::new(false)); + let observed = reached.clone(); + ATTACH_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase == checkpoint { + observed.set(true); + if cancel { + observed_cancel.cancel(); + } else { + ATTACH_TEST_NOW.with(|clock| { + clock.set(Some(Instant::now() + Duration::from_secs(30))) + }); + } + } + })) + }); + let capture = TestSystemdUnitNameCapture::start(); + let error = run_process_cancellable( + ProcessSpec::shell( + "stale attach proof", + Shell::UnixSh, + format!("touch '{}'", marker.display()), + temp.path(), + 128, + ) + .with_timeout(Some(Duration::from_secs(12))), + &cancellation, + ) + .unwrap_err(); + assert!(reached.get(), "must exercise {checkpoint}: {error:?}"); + if cancel { + assert!(error.is_cancelled()); + assert!(error + .cancellation_evidence() + .unwrap() + .process_tree + .is_verified_empty()); + assert!(error + .cancellation_evidence() + .unwrap() + .process_error + .as_ref() + .unwrap() + .contains("phase=")); + } else { + assert!( + matches!(error, ProcessRunError::ProcessOwnership { ref source, .. } if source.kind() == io::ErrorKind::TimedOut), + "{error:?}" + ); + assert!(error.to_string().contains("attach_allowance_ms=")); + } + assert!(!marker.exists()); + assert_systemd_units_have_no_residue(&capture.finish()); + } + } +} + +#[cfg(target_os = "linux")] +#[test] +fn sandbox_property_probe_obeys_attach_deadline_and_cancellation() { + let temp = tempfile::tempdir().unwrap(); + for cancel in [false, true] { + let _guard = AttachTestGuard; + let now = Instant::now(); + ATTACH_TEST_NOW.with(|clock| clock.set(Some(now))); + let pid_file = temp + .path() + .join(if cancel { "cancel-pid" } else { "timeout-pid" }); + let cancellation = ProcessCancellation::new(); + let signal = cancellation.clone(); + let child_pid_file = pid_file.clone(); + ATTACH_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase == "before_control_budget_check" + && fs::read_to_string(&child_pid_file) + .ok() + .and_then(|pid| pid.trim().parse::().ok()) + .is_some() + { + if cancel { + signal.cancel(); + } else { + ATTACH_TEST_NOW.with(|clock| { + clock.set(Some(Instant::now() + Duration::from_secs(30))) + }); + } + } + })); + }); + let args = [ + OsString::from("-c"), + OsString::from(format!( + "echo $$ > '{}'; exec /bin/sleep 30", + pid_file.display() + )), + ]; + let error = run_control_command_capture_bounded_until( + Path::new("/bin/sh"), + &args, + "bounded property fixture", + temp.path(), + None, + &cancellation, + ) + .unwrap_err(); + assert_eq!( + error.kind(), + if cancel { + io::ErrorKind::Interrupted + } else { + io::ErrorKind::TimedOut + } + ); + let pid = fs::read_to_string(pid_file).unwrap(); + assert_process_gone(&pid, "property fixture must be reaped"); + } + let cancellation = ProcessCancellation::new(); + cancellation.cancel(); + let marker = temp.path().join("never-started"); + let args = [ + OsString::from("-c"), + OsString::from(format!("touch '{}'", marker.display())), + ]; + let error = run_control_command_capture_bounded_until( + Path::new("/bin/sh"), + &args, + "cancelled before spawn", + temp.path(), + Some(Instant::now()), + &cancellation, + ) + .unwrap_err(); + assert_eq!(error.kind(), io::ErrorKind::Interrupted); + assert!(!marker.exists()); + for cancel in [false, true] { + let _guard = AttachTestGuard; + ATTACH_TEST_NOW.with(|clock| clock.set(Some(Instant::now()))); + let cancellation = ProcessCancellation::new(); + let signal = cancellation.clone(); + let observed = std::rc::Rc::new(std::cell::Cell::new(false)); + let reached = observed.clone(); + ATTACH_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase == "before_control_success" { + reached.set(true); + if cancel { + signal.cancel(); + } else { + ATTACH_TEST_NOW.with(|clock| { + clock.set(Some(Instant::now() + Duration::from_secs(30))) + }); + } + } + })) + }); + let error = run_control_command_capture_bounded_until( + Path::new("/bin/true"), + &[], + "late property success", + temp.path(), + None, + &cancellation, + ) + .unwrap_err(); + assert!(observed.get()); + assert_eq!( + error.kind(), + if cancel { + io::ErrorKind::Interrupted + } else { + io::ErrorKind::TimedOut + } + ); + } + let (status, _, _) = run_control_command_capture_bounded( + Path::new("/bin/true"), + &[], + "legacy control cap", + temp.path(), + ) + .unwrap(); + assert!(status.success()); +} + #[cfg(target_os = "linux")] #[test] fn exhausted_total_budget_returns_typed_setup_timeout_without_starting_target() { diff --git a/src/process_runner/tests_part2.rs b/src/process_runner/tests_part2.rs index 3d8cac4a..e8f1c43d 100644 --- a/src/process_runner/tests_part2.rs +++ b/src/process_runner/tests_part2.rs @@ -723,6 +723,7 @@ "sh", None, &cancellation, + &mut PhaseTimings::new(Instant::now(), None, Duration::MAX, Duration::ZERO, "fixture"), ) .expect("prepare evidence containment"); let mut command = prepared_tree @@ -734,7 +735,7 @@ .stderr(Stdio::piped()); let mut child = command.spawn().expect("spawn evidence child"); let attached_tree = prepared_tree - .attach(&mut child, "evidence child", "sh", None, &cancellation) + .attach(&mut child, "evidence child", "sh", None, &cancellation, &mut PhaseTimings::new(Instant::now(), None, Duration::MAX, Duration::ZERO, "fixture")) .expect("attach evidence child"); let prepared = PreparedChildIo::take(&mut child, &StdinMode::Null) .expect("prepare evidence child I/O"); @@ -1235,6 +1236,7 @@ "no-systemd-probe", None, &cancellation, + &mut PhaseTimings::new(Instant::now(), None, Duration::MAX, Duration::ZERO, "fixture"), ) .expect("trusted simulation compatibility must not require systemd"); diff --git a/src/worktree.rs b/src/worktree.rs index 1e1d8afc..ae3ce20e 100644 --- a/src/worktree.rs +++ b/src/worktree.rs @@ -160,8 +160,8 @@ const WORKTREE_STATUS_LOCK_TIMEOUT: Duration = Duration::from_secs(60); // lease; the 60-second budget stays the bound for registry commits only. const MANAGED_WORKTREE_REGISTRY_LOCK_TIMEOUT: Duration = Duration::from_secs(60); // Verified Git commands can spend 30 seconds acquiring a containment slot -// before the three-second start-gate handshakes. Include setup headroom in the -// command cap on loaded hosts; the caller's absolute deadline still wins. +// before deadline-clipped adaptive attachment (up to ten seconds). Include setup +// headroom in the command cap on loaded hosts; the caller's absolute deadline still wins. const WORKTREE_STATUS_COMMAND_TIMEOUT: Duration = Duration::from_secs(40); // Leave room for private filesystem staging and the remaining Git commands // after one slow containment setup. Final runtime cleanup is separately bound. diff --git a/src/worktree/part4.rs b/src/worktree/part4.rs index abd278d7..f3476314 100644 --- a/src/worktree/part4.rs +++ b/src/worktree/part4.rs @@ -87,10 +87,14 @@ fn bounded_worktree_records_mode( ) -> Result { let (_process_lock, deadline, process_queue_wait) = enter_bounded_status_process_scope(timeout)?; + let mut timings = crate::process_runner::PhaseTimings::new( + deadline - timeout, Some(deadline), timeout, process_queue_wait, "runtime_root_setup", + ); + let result = (|| { ensure_worktree_status_deadline(deadline, "before bounded-status runtime-root setup")?; let state_root = bounded_status_runtime_root(path)?; ensure_worktree_status_deadline(deadline, "after bounded-status runtime-root setup")?; - let mut records = bounded_worktree_status_in_runtime_until( + let mut records = bounded_worktree_status_in_runtime_until_timed( path, max_entries, max_output_bytes, @@ -99,9 +103,101 @@ fn bounded_worktree_records_mode( deadline, collect_ignored, isolation, + &mut timings, )?; records.process_queue_wait = process_queue_wait; Ok(records) + })(); + diagnose_bounded_status_result(result, &timings) +} + +fn diagnose_bounded_status_result(result: Result, timings: &crate::process_runner::PhaseTimings) -> Result { + let summary = timings.snapshot(worktree_status_now()); + tracing::debug!(timings = %summary, completed = result.is_ok(), "bounded-status main operation finished"); + result.map_err(|error| { + append_bounded_status_diagnostics(error, format!("bounded-status main timing: {summary}")) + }) +} + +fn append_bounded_status_diagnostics( + error: anyhow::Error, + diagnostics: impl std::fmt::Display, +) -> anyhow::Error { + // Keep the original Display classification and anyhow's typed cause chain. + // Do not expand the source chain here: inner errors can contain sensitive data. + // Callers must also summarize secondary failures without their private paths. + let message = format!("{error}; {diagnostics}"); + error.context(message) +} + +/// Copy only known classification labels, never the secondary error's dynamic +/// text or source chain. Unknown errors still receive the redacted category. +fn redacted_bounded_status_secondary(error: &anyhow::Error, category: &str) -> String { + const CLASSIFICATIONS: &[&str] = &[ + "failed to remove bounded-status private runtime", + "private directory scavenging exceeded its total time budget", + "private directory scavenging limits must be non-zero", + "private directory scavenging deadline overflowed", + "worktree status exhausted its total time budget", + "worktree status total time budget overflowed", + "unexpected entry in private residue root requires manual inspection", + "private residue root is missing its held stable lock file", + "private residue root contains duplicate directory identities", + "private residue tree exceeded its bounded safety contract", + "private residue lock is unsafe or changed", + "private residue entry is not an owner-private directory", + "private residue directory identity changed while binding", + "private residue directory changed before bounded audit", + "private residue quarantine does not encode a canonical source name", + "private residue quarantine identity is malformed or changed", + "private residue entry changed owner or filesystem", + "private residue directory has unsafe mode", + "private residue directory identity changed", + "private residue file is not owner-private and single-link", + "private residue symlink has an unsafe link count", + "private residue contains a special file", + "held directory binding changed", + "directory pathname binding disappeared", + "directory pathname binding changed", + "held regular-file binding changed", + "regular-file pathname binding disappeared", + "regular-file pathname binding changed", + "Git directory association marker changed", + "kernel state lock was presented with a different root inode", + "kernel state lock descriptor identity changed unexpectedly", + "kernel state lock path does not name its opened descriptor", + "kernel state lock path was rebound while its original inode remained locked", + "kernel state lock is not an owner-private single-link regular file", + "safe root path is no longer reachable", + "safe root identity changed", + "safe root path was replaced", + "safe root mount binding changed", + "safe root mount id changed", + ]; + let mut labels = Vec::new(); + for cause in error.chain() { + let message = cause.to_string(); + for &label in CLASSIFICATIONS { + if (message == label + || message.strip_prefix(label).is_some_and(|suffix| { + suffix.starts_with(": ") + || suffix.starts_with(" at ") + || (label == "worktree status exhausted its total time budget" + && [" before ", " after ", " during "] + .iter() + .any(|&phase| suffix.starts_with(phase))) + })) + && !labels.contains(&label) + { + labels.push(label); + } + } + } + if labels.is_empty() { + format!("") + } else { + format!("{}: ", labels.join(": ")) + } } fn enter_bounded_status_process_scope( @@ -175,6 +271,7 @@ where .map(|records| records.status.is_empty()) } +#[cfg(test)] #[allow(clippy::too_many_arguments)] fn bounded_worktree_status_in_runtime_until( path: &Path, @@ -189,9 +286,32 @@ fn bounded_worktree_status_in_runtime_until( where F: FnOnce(&SafeRoot) -> Result<()>, { + let now = worktree_status_now(); + let mut timings = crate::process_runner::PhaseTimings::new(now, Some(deadline), deadline.saturating_duration_since(now), Duration::ZERO, "repository_binding"); + let result = bounded_worktree_status_in_runtime_until_timed(path, max_entries, max_output_bytes, state_root, after_index_snapshot, deadline, collect_ignored, isolation, &mut timings); + diagnose_bounded_status_result(result, &timings) +} + +#[allow(clippy::too_many_arguments)] +fn bounded_worktree_status_in_runtime_until_timed( + path: &Path, + max_entries: usize, + max_output_bytes: usize, + state_root: &SafeRoot, + after_index_snapshot: F, + deadline: Instant, + collect_ignored: bool, + isolation: BoundedGitIsolation, + timings: &mut crate::process_runner::PhaseTimings, +) -> Result +where + F: FnOnce(&SafeRoot) -> Result<()>, +{ + timings.enter("repository_binding", worktree_status_now()); let repository_binding = RepositoryBindingGuard::bind(path) .context("failed to bind bounded-status repository association")?; let worktree_binding = repository_binding.worktree_binding(); + timings.enter("kernel_runtime_lock", worktree_status_now()); let lock_timeout = remaining_worktree_status_time( deadline, "before global bounded-status runtime lock acquisition", @@ -205,10 +325,12 @@ where .context("failed to acquire global bounded-status runtime lock")?; ensure_worktree_status_deadline(deadline, "after bounded-status runtime lock acquisition")?; status_lock.verify_direct_binding(state_root)?; + timings.enter("startup_scavenging", worktree_status_now()); scavenge_bounded_status_runtimes_until(state_root, WORKTREE_STATUS_SCAVENGE_LIMITS, deadline) .context("failed to scavenge bounded-status crash residue")?; status_lock.verify_direct_binding(state_root)?; ensure_worktree_status_deadline(deadline, "after bounded-status startup cleanup")?; + timings.enter("metadata_validation", worktree_status_now()); let git_dir_binding = DirectoryBindingGuard::bind(repository_binding.git_dir()) .context("failed to bind bounded-status Git directory")?; let common_dir_binding = DirectoryBindingGuard::bind(repository_binding.common_dir()) @@ -216,12 +338,14 @@ where verify_repository_status_bindings(worktree_binding, &git_dir_binding, &common_dir_binding)?; let git_text_inputs = validate_bounded_git_text_inputs_bound(&repository_binding, deadline)?; ensure_worktree_status_deadline(deadline, "after opening bounded-status repository")?; + timings.enter("head_capture", worktree_status_now()); let raw_head = repository_binding .read_git_relative(Path::new("HEAD"), MAX_WORKTREE_HEAD_BYTES) .context("failed to capture bounded-status HEAD")?; validate_bounded_head(&raw_head)?; let head = resolve_bounded_head(&repository_binding, &raw_head)?; ensure_worktree_status_deadline(deadline, "after capturing bounded-status HEAD")?; + timings.enter("index_capture_validation", worktree_status_now()); let index = repository_binding .read_git_relative_optional(Path::new("index"), MAX_WORKTREE_INDEX_BYTES) .context("failed to capture bounded-status index")?; @@ -229,17 +353,23 @@ where validate_bounded_index_bytes(index)?; } ensure_worktree_status_deadline(deadline, "after capturing bounded-status index")?; + timings.enter("objects_binding", worktree_status_now()); let common_objects = SafeRoot::open_existing(repository_binding.common_dir().join("objects"))?; ensure_worktree_status_deadline(deadline, "after binding bounded-status objects")?; + timings.enter("runtime_reservation", worktree_status_now()); let runtime = state_root.reserve_random_direct_child_directory(WORKTREE_STATUS_RUNTIME_SEED)?; let result = (|| -> Result { ensure_worktree_status_deadline(deadline, "after reserving bounded-status runtime")?; + timings.enter("runtime_open", worktree_status_now()); let runtime_root = SafeRoot::open_existing(runtime.path())?; ensure_worktree_status_deadline(deadline, "after opening bounded-status runtime")?; + timings.enter("home_setup", worktree_status_now()); runtime_root.reserve_direct_child_directory("home")?; ensure_worktree_status_deadline(deadline, "after bounded-status HOME setup")?; + timings.enter("tmp_setup", worktree_status_now()); runtime_root.reserve_direct_child_directory("tmp")?; ensure_worktree_status_deadline(deadline, "after bounded-status TMP setup")?; + timings.enter("git_root_setup", worktree_status_now()); let git_dir = runtime_root.reserve_direct_child_directory("git")?; let git_root = SafeRoot::open_existing(git_dir.path())?; git_root.reserve_direct_child_directory("refs")?; @@ -249,16 +379,29 @@ where AtomicStateWriter::write_direct(&info_root, "exclude", exclude)?; } ensure_worktree_status_deadline(deadline, "after bounded-status Git root setup")?; + #[cfg(test)] + worktree_status_test_checkpoint("before_index_staging"); + timings.enter("index_staging", worktree_status_now()); if let Some(index) = &index { AtomicStateWriter::write_direct(&git_root, "index", index)?; } ensure_worktree_status_deadline(deadline, "after bounded-status index staging")?; + #[cfg(test)] + worktree_status_test_checkpoint("before_callback"); + timings.enter("callback", worktree_status_now()); after_index_snapshot(&runtime_root)?; ensure_worktree_status_deadline(deadline, "after bounded-status setup callback")?; + #[cfg(test)] + worktree_status_test_checkpoint("before_head_staging"); + timings.enter("head_staging", worktree_status_now()); AtomicStateWriter::write_direct(&git_root, "HEAD", &head)?; + #[cfg(test)] + worktree_status_test_checkpoint("after_head_staging"); ensure_worktree_status_deadline(deadline, "after bounded-status HEAD staging")?; + timings.enter("object_link", worktree_status_now()); create_validated_object_link(&git_root, common_objects.path())?; ensure_worktree_status_deadline(deadline, "after bounded-status object-link setup")?; + timings.enter("worktree_link", worktree_status_now()); let worktree_alias = create_bounded_status_worktree_link(&runtime_root, path)?; ensure_worktree_status_deadline(deadline, "after bounded-status worktree-link setup")?; let git_context = BoundedGitContext { @@ -270,6 +413,7 @@ where core_filemode: git_text_inputs.core_filemode, isolation, }; + timings.enter("git_index_listing", worktree_status_now()); let visible = run_bounded_git_records( &git_context, [ @@ -286,6 +430,7 @@ where "bounded managed-worktree index listing", )?; ensure_worktree_status_deadline(deadline, "after bounded managed-worktree index listing")?; + timings.enter("git_index_flag_validation", worktree_status_now()); let index_flags = run_bounded_git_records( &git_context, [ @@ -302,6 +447,7 @@ where "bounded managed-worktree index flag validation", )?; validate_bounded_git_index_records(&index_flags, max_entries)?; + timings.enter("git_fsmonitor_validation", worktree_status_now()); let fsmonitor_flags = run_bounded_git_records( &git_context, [ @@ -318,6 +464,7 @@ where "bounded managed-worktree fsmonitor flag validation", )?; validate_bounded_git_index_records(&fsmonitor_flags, max_entries)?; + timings.enter("git_status", worktree_status_now()); let bytes = run_bounded_git_records( &git_context, [ @@ -343,6 +490,7 @@ where .checked_sub(bytes.len()) .context("bounded worktree status exceeded its combined output limit")?; let ignored = if collect_ignored { + timings.enter("git_ignored_listing", worktree_status_now()); let ignored = run_bounded_git_records( &git_context, [ @@ -379,7 +527,9 @@ where } else { Vec::new() }; + timings.enter("repository_verification", worktree_status_now()); verify_repository_status_bindings(worktree_binding, &git_dir_binding, &common_dir_binding)?; + ensure_worktree_status_deadline(deadline, "after bounded-status repository verification")?; Ok(BoundedWorktreeRecords { visible, status: bytes, @@ -388,20 +538,30 @@ where cleanup_elapsed: Duration::ZERO, }) })(); + // Cleanup has a separate budget; it must not become part of the failing main phase. + timings.freeze(worktree_status_now()); let finished = finish_bounded_status_runtime(result, state_root, &status_lock).map( |(mut records, cleanup_elapsed)| { records.cleanup_elapsed = cleanup_elapsed; records }, ); + let verification_started = worktree_status_now(); let finished = finish_with_status_lock_verification( finished, status_lock.verify_direct_binding(state_root), ); - finish_with_repository_binding_verification( + let lock_elapsed = worktree_status_now().saturating_duration_since(verification_started); + let repository_started = worktree_status_now(); + let finished = finish_with_repository_binding_verification( finished, repository_binding.verify_status_generation(), - ) + ); + let repository_elapsed = worktree_status_now().saturating_duration_since(repository_started); + tracing::debug!(lock_verification_ms = lock_elapsed.as_millis(), repository_verification_ms = repository_elapsed.as_millis(), "bounded-status final verification finished"); + finished.map_err(|error| { + append_bounded_status_diagnostics(error, format!("bounded-status final verification: lock_elapsed_ms={} repository_elapsed_ms={}", lock_elapsed.as_millis(), repository_elapsed.as_millis())) + }) } /// Final cleanup has its own finite budget. A main-operation timeout must not @@ -432,14 +592,22 @@ fn finish_bounded_status_runtime( completed = cleanup.is_ok(), "bounded-status private runtime cleanup finished" ); - match (result, cleanup) { + let cleanup_completed = cleanup.is_ok(); + let finished = match (result, cleanup) { (Ok(value), Ok(_)) => Ok((value, cleanup_elapsed)), (Err(error), Ok(_)) => Err(error), (Ok(_), Err(cleanup_error)) => Err(cleanup_error), - (Err(error), Err(cleanup_error)) => Err(error.context(format!( - "bounded-status runtime cleanup also failed: {cleanup_error:#}" - ))), - } + (Err(error), Err(cleanup_error)) => Err(append_bounded_status_diagnostics( + error, + format!( + "bounded-status runtime cleanup also failed: {}", + redacted_bounded_status_secondary(&cleanup_error, "cleanup") + ), + )), + }; + finished.map_err(|error| { + append_bounded_status_diagnostics(error, format!("bounded-status cleanup: elapsed_ms={} completed={cleanup_completed}", cleanup_elapsed.as_millis())) + }) } fn validate_bounded_head(bytes: &[u8]) -> Result<()> { @@ -495,9 +663,13 @@ fn finish_with_repository_binding_verification( (Ok(value), Ok(())) => Ok(value), (Err(error), Ok(())) => Err(error), (Ok(_), Err(binding_error)) => Err(binding_error), - (Err(error), Err(binding_error)) => Err(error.context(format!( - "operation also lost its repository pathname binding: {binding_error:#}" - ))), + (Err(error), Err(binding_error)) => Err(append_bounded_status_diagnostics( + error, + format!( + "operation also lost its repository pathname binding: {}", + redacted_bounded_status_secondary(&binding_error, "binding") + ), + )), } } @@ -1212,9 +1384,13 @@ fn finish_with_status_lock_verification( (Ok(value), Ok(())) => Ok(value), (Err(error), Ok(())) => Err(error), (Ok(_), Err(lock_error)) => Err(lock_error), - (Err(error), Err(lock_error)) => Err(error.context(format!( - "operation also lost its bounded-status lock-path binding: {lock_error:#}" - ))), + (Err(error), Err(lock_error)) => Err(append_bounded_status_diagnostics( + error, + format!( + "operation also lost its bounded-status lock-path binding: {}", + redacted_bounded_status_secondary(&lock_error, "lock") + ), + )), } } @@ -1271,8 +1447,21 @@ fn worktree_status_now() -> Instant { Instant::now() } +#[cfg(test)] +type WorktreeStatusTestHook = Box; + +#[cfg(test)] +fn worktree_status_test_checkpoint(phase: &'static str) { + WORKTREE_STATUS_TEST_HOOK.with(|hook| { + if let Some(hook) = hook.borrow_mut().as_mut() { + hook(phase); + } + }); +} + #[cfg(test)] thread_local! { + static WORKTREE_STATUS_TEST_HOOK: std::cell::RefCell> = const { std::cell::RefCell::new(None) }; static WORKTREE_STATUS_TEST_CLOCK: std::cell::Cell> = const { std::cell::Cell::new(None) }; @@ -1599,8 +1788,6 @@ fn run_bounded_git_records( ) -> Result> { let git = crate::merge::resolve_trusted_executable("git") .context("failed to resolve trusted Git for bounded worktree status")?; - let remaining = remaining_worktree_status_time(deadline, "before bounded Git command")? - .min(WORKTREE_STATUS_COMMAND_TIMEOUT); context.runtime_root.verify()?; let mut environment = BTreeMap::new(); environment.insert("GIT_ATTR_NOSYSTEM".to_string(), "1".to_string()); @@ -1651,6 +1838,9 @@ fn run_bounded_git_records( if !context.objects_target.starts_with(context.worktree_target) { side_effects = side_effects.with_visible_read_only_root(context.objects_target); } + // Spec preparation spends the caller's original budget, never a renewed duration. + let remaining = remaining_worktree_status_time(deadline, "before bounded Git command")? + .min(WORKTREE_STATUS_COMMAND_TIMEOUT); let spec = ProcessSpec::direct( label, git, @@ -1660,7 +1850,8 @@ fn run_bounded_git_records( ) .with_environment(EnvironmentMode::ClearAndSet(environment)) .with_stdin(StdinMode::Null) - .with_timeout(Some(remaining)); + .with_timeout(Some(remaining)) + .with_absolute_deadline(deadline); let spec = match context.isolation { BoundedGitIsolation::Verified => spec .with_containment(ContainmentPolicy::Required) @@ -1669,6 +1860,7 @@ fn run_bounded_git_records( )), BoundedGitIsolation::Trusted => spec.with_containment(ContainmentPolicy::TrustedBestEffort), }; + ensure_worktree_status_deadline(deadline, "before bounded Git launch")?; let started = Instant::now(); let output = run_process(spec); tracing::debug!( @@ -1696,6 +1888,9 @@ fn run_bounded_git_records( let stderr = output.stderr.summarize_chars(512); bail!("worktree status command failed: {}", stderr.text); } + #[cfg(test)] + worktree_status_test_checkpoint("after_bounded_git_validation"); + ensure_worktree_status_deadline(deadline, "after bounded Git command validation")?; let bytes = output.stdout.as_bytes(); if !bytes.is_empty() && !bytes.ends_with(&[0]) { bail!("worktree status returned a malformed non-NUL-terminated record"); @@ -1704,7 +1899,9 @@ fn run_bounded_git_records( if entries > max_entries { bail!("worktree status reported {entries} entries, exceeding its limit of {max_entries}"); } - Ok(bytes.to_vec()) + let records = bytes.to_vec(); + ensure_worktree_status_deadline(deadline, "after bounded Git records validation")?; + Ok(records) } #[cfg(test)] diff --git a/src/worktree/tests_part2.rs b/src/worktree/tests_part2.rs index 1b304785..c0c66137 100644 --- a/src/worktree/tests_part2.rs +++ b/src/worktree/tests_part2.rs @@ -1615,10 +1615,261 @@ #[cfg(target_os = "linux")] struct WorktreeStatusTestClockGuard; + #[cfg(target_os = "linux")] + #[test] + fn bounded_status_phase_diagnostics_distinguish_prior_setup_from_head_staging() { + let _clock_guard = WorktreeStatusTestClockGuard; + let started = Instant::now(); + let deadline = started + Duration::from_secs(60); + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started))); + let temp = TempDir::new().unwrap(); + let repo_path = temp.path().join("repo"); + WorktreeManager::init_repository(&repo_path, "main").unwrap(); + let repo = crate::git_repository::open(&repo_path).unwrap(); + commit_readme(&repo).unwrap(); + let root = SafeRoot::open_or_create(temp.path().join("status-root")).unwrap(); + WORKTREE_STATUS_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + let elapsed = match phase { + "before_index_staging" => 0, + "before_callback" => 25, + "before_head_staging" => 59, + "after_head_staging" => 61, + _ => return, + }; + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started + Duration::from_secs(elapsed)))); + })); + }); + let error = bounded_worktree_status_in_runtime_until( + &repo_path, MAX_WORKTREE_STATUS_ENTRIES, MAX_WORKTREE_STATUS_OUTPUT_BYTES, + &root, |_| Ok(()), deadline, false, BoundedGitIsolation::Verified, + ).err().expect("deadline must refuse completion"); + let message = format!("{error:#}"); + assert_status_root_contains_only_lock(&root); + for expected in ["after bounded-status HEAD staging", "phase=head_staging phase_elapsed_ms=2000", "index_staging=25000ms", "callback=34000ms", "largest_phase=callback", "admitted_elapsed_ms=61000"] { + assert!(message.contains(expected), "missing {expected}: {message}"); + } + } + + #[cfg(target_os = "linux")] + #[test] + fn bounded_git_records_reject_success_observed_after_deadline() { + let _clock_guard = WorktreeStatusTestClockGuard; + let temp = TempDir::new().unwrap(); + let repo_path = temp.path().join("repo"); + WorktreeManager::init_repository(&repo_path, "main").unwrap(); + let repo = crate::git_repository::open(&repo_path).unwrap(); + commit_readme(&repo).unwrap(); + let root = SafeRoot::open_or_create(temp.path().join("status-root")).unwrap(); + let started = Instant::now(); + let deadline = started + WORKTREE_STATUS_TIMEOUT; + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started))); + let reached = std::rc::Rc::new(std::cell::Cell::new(false)); + let observed = reached.clone(); + WORKTREE_STATUS_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase == "after_bounded_git_validation" { + observed.set(true); + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(deadline + Duration::from_secs(1)))); + } + })); + }); + let error = bounded_worktree_status_in_runtime_until( + &repo_path, MAX_WORKTREE_STATUS_ENTRIES, MAX_WORKTREE_STATUS_OUTPUT_BYTES, + &root, |_| Ok(()), deadline, false, BoundedGitIsolation::Trusted, + ).err().expect("deadline must refuse completion"); + assert!(reached.get(), "must run and validate the real Git command: {error:#}"); + let message = format!("{error:#}"); + assert!(message.contains("after bounded Git command validation"), "{message}"); + assert!(message.contains("phase=git_index_listing"), "{message}"); + assert_status_root_contains_only_lock(&root); + } + + #[test] + fn bounded_status_diagnostics_preserve_display_and_typed_cause() { + let cause = std::io::Error::new( + std::io::ErrorKind::PermissionDenied, + "secret=hidden-token /private/hidden-path", + ); + let error = anyhow::Error::new(cause).context("original classified failure"); + let error = append_bounded_status_diagnostics(error, "bounded-status cleanup: completed=true"); + let started = Instant::now(); + let timings = crate::process_runner::PhaseTimings::new( + started, None, Duration::from_secs(60), Duration::ZERO, "callback", + ); + let error = diagnose_bounded_status_result::<()>(Err(error), &timings).unwrap_err(); + let message = error.to_string(); + assert!(message.starts_with("original classified failure; bounded-status cleanup:"), "{message}"); + assert!(message.contains("bounded-status main timing: phase=callback"), "{message}"); + for hidden in ["hidden-token", "/private/hidden-path"] { + assert!(!message.contains(hidden), "diagnostics exposed a hidden source: {message}"); + } + let cause = error.downcast_ref::().expect("typed cause retained"); + assert_eq!(cause.kind(), std::io::ErrorKind::PermissionDenied); + assert!(error.root_cause().is::()); + } + + #[cfg(target_os = "linux")] + #[test] + fn bounded_status_both_fail_diagnostics_redact_secondary_paths() { + let temp = TempDir::new().expect("tempdir"); + let root = SafeRoot::open_or_create(temp.path().join("private-status-root")) + .expect("runtime root"); + let lock = KernelStateLock::acquire_direct_with_timeout( + &root, + WORKTREE_STATUS_RUNTIME_LOCK, + Duration::from_secs(1), + ) + .expect("runtime lock"); + let private_path = root.path().join("unexpected-private-entry"); + fs::write(&private_path, "unexpected").expect("inject cleanup failure"); + let private_path = private_path.display().to_string(); + let cleanup_error = + scavenge_bounded_status_runtimes(&root, WORKTREE_STATUS_SCAVENGE_LIMITS) + .expect_err("unexpected entry must fail cleanup"); + assert!(format!("{cleanup_error:#}").contains(&private_path)); + let deadline_error = anyhow::anyhow!( + "worktree status exhausted its total time budget after {private_path}" + ); + assert_eq!( + redacted_bounded_status_secondary(&deadline_error, "cleanup"), + "worktree status exhausted its total time budget: " + ); + + let operation_error = || { + anyhow::Error::new(std::io::Error::new( + std::io::ErrorKind::PermissionDenied, + "original typed cause", + )) + .context("original classified failure") + }; + let binding_error = || { + anyhow::anyhow!("directory pathname binding disappeared: {private_path}") + .context(format!("verification failed at {private_path}")) + }; + let results = [ + ( + "runtime cleanup also failed", + &[ + "failed to remove bounded-status private runtime", + "unexpected entry in private residue root requires manual inspection", + ][..], + finish_bounded_status_runtime::<()>(Err(operation_error()), &root, &lock) + .map(|_| ()), + ), + ( + "repository pathname binding", + &["directory pathname binding disappeared"][..], + finish_with_repository_binding_verification::<()>( + Err(operation_error()), + Err(binding_error()), + ), + ), + ( + "bounded-status lock-path binding", + &["kernel state lock path does not name its opened descriptor"][..], + finish_with_status_lock_verification::<()>( + Err(operation_error()), + Err(anyhow::anyhow!( + "kernel state lock path does not name its opened descriptor: {private_path}" + )), + ), + ), + ( + "repository pathname binding", + &[][..], + finish_with_repository_binding_verification::<()>( + Err(operation_error()), + Err(anyhow::anyhow!( + "unknown failure at {private_path}: directory pathname binding changed" + )), + ), + ), + ]; + for (secondary, classifications, result) in results { + let started = Instant::now(); + let timings = crate::process_runner::PhaseTimings::new( + started, + None, + Duration::from_secs(60), + Duration::ZERO, + "callback", + ); + let error = diagnose_bounded_status_result(result, &timings).unwrap_err(); + for message in [error.to_string(), format!("{error:#}")] { + assert!( + message.starts_with("original classified failure; "), + "{message}" + ); + assert!(message.contains(secondary), "{message}"); + for &classification in classifications { + assert!( + message.contains(classification), + "missing {classification}: {message}" + ); + } + for hidden in [ + "verification failed at", + "unknown failure at", + "directory pathname binding changed", + ] { + assert!(!message.contains(hidden), "{message}"); + } + assert!(message.contains("() + .expect("typed cause retained"); + assert_eq!(cause.kind(), std::io::ErrorKind::PermissionDenied); + assert_eq!(cause.to_string(), "original typed cause"); + assert!(error.root_cause().is::()); + } + } + + #[cfg(target_os = "linux")] + #[test] + fn bounded_status_failure_diagnostics_exclude_queue_and_separate_cleanup() { + let _clock_guard = WorktreeStatusTestClockGuard; + let temp = TempDir::new().unwrap(); + let root = SafeRoot::open_or_create(temp.path().join("status-root")).unwrap(); + let lock = KernelStateLock::acquire_direct_with_timeout(&root, WORKTREE_STATUS_RUNTIME_LOCK, Duration::from_secs(1)).unwrap(); + for cleanup_fails in [false, true] { + let started = Instant::now(); + let main_end = started + Duration::from_secs(61); + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(main_end))); + let mut timings = crate::process_runner::PhaseTimings::new(started, Some(started + Duration::from_secs(60)), Duration::from_secs(60), Duration::from_secs(120), "head_staging"); + timings.freeze(worktree_status_now()); + let _hook = crate::safe_state::set_scavenge_deadline_hook(move |phase| { + if phase == "before private directory scavenging" { + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(main_end + Duration::from_secs(if cleanup_fails { 31 } else { 2 })))); + } + false + }); + let main: Result<()> = Err(std::io::Error::other("original main failure").into()); + let result = finish_bounded_status_runtime(main, &root, &lock); + let error = diagnose_bounded_status_result(result, &timings).unwrap_err(); + assert!(error.downcast_ref::().is_some(), "typed main cause retained"); + let message = error.to_string(); + assert!(message.starts_with("original main failure; "), "{message}"); + for expected in ["original main failure", "queue_wait_ms=120000", "admitted_elapsed_ms=61000", "phase_elapsed_ms=61000", "budget_ms=60000 remaining_ms=0"] { + assert!(message.contains(expected), "missing {expected}: {message}"); + } + assert!(message.contains(if cleanup_fails { "cleanup: elapsed_ms=31000 completed=false" } else { "cleanup: elapsed_ms=2000 completed=true" }), "{message}"); + assert_eq!(message.contains("cleanup also failed"), cleanup_fails, "{message}"); + } + } + #[cfg(target_os = "linux")] impl Drop for WorktreeStatusTestClockGuard { fn drop(&mut self) { WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(None)); + WORKTREE_STATUS_TEST_HOOK.with(|hook| hook.borrow_mut().take()); } } @@ -1661,6 +1912,17 @@ message.contains("after bounded-status setup callback"), "{message}" ); + // Exercise the production phase boundaries and frozen main snapshot, + // in addition to the accumulator's deterministic arithmetic tests. + for expected in [ + "phase=callback phase_elapsed_ms=61000", + "admitted_elapsed_ms=61000", + "largest_phase=callback", + "bounded-status cleanup:", + "completed=true", + ] { + assert!(message.contains(expected), "missing {expected}: {message}"); + } assert!(!message.contains("cleanup also failed"), "{message}"); assert_status_root_contains_only_lock(&runtime_root); }