From 5b5588f5d18bcfd6ea4e219a9d77ffaa7b362368 Mon Sep 17 00:00:00 2001 From: Meta-Develop <116134763+Meta-Develop@users.noreply.github.com> Date: Sat, 24 Oct 2026 06:25:26 +0900 Subject: [PATCH 1/8] Report worktree status phase latency and clip attach grace to the remaining deadline Child worktree creation on slow hosts failed either at the 60 s bounded-status budget or at the 3 s systemd attach grace without saying which phase spent the time. Record per-phase latency in these failures, exclude queue and lock waits from the execution budget, and scale the attach grace within the remaining absolute deadline. Ownership and containment proof, rollback, and cancellation are unchanged. --- src/process_runner.rs | 244 +++++++++++++++++-- src/process_runner/part2.rs | 20 +- src/process_runner/part3.rs | 221 +++++++++++++---- src/process_runner/tests.rs | 387 ++++++++++++++++++++++++++++++ src/process_runner/tests_part2.rs | 4 +- src/worktree.rs | 4 +- src/worktree/part4.rs | 93 ++++++- src/worktree/tests_part2.rs | 63 +++++ 8 files changed, 946 insertions(+), 90 deletions(-) diff --git a/src/process_runner.rs b/src/process_runner.rs index 47f26899..4c15c614 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) => { @@ -4778,10 +4960,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..23b3ef23 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,25 @@ 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) { + 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 +928,7 @@ impl PreparedProcessTree { ), side_effects: self.side_effects, process_error: Some(format!( - "{label} was cancelled by its run supervisor" + "{label} was cancelled by its run supervisor; {source}" )), stdin_error: None, })), diff --git a/src/process_runner/part3.rs b/src/process_runner/part3.rs index 90a8c185..f00ddd17 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,43 @@ 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<()> { + 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 +1094,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 - ), - )); - } + check_attach_budget(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 +1117,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 +1135,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 +1169,23 @@ impl SystemdUnit { } } if self.environment_published && !self.environment_released { + check_attach_budget(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), } } + check_attach_budget(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 +1202,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()? { @@ -1210,24 +1231,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 +1683,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 +1697,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 +1728,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 +1767,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 +1781,22 @@ 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()?; + if let Err(error) = check_attach_budget(deadline, cancellation) { 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 +1812,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 +2337,59 @@ 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)] + ATTACH_TEST_HOOK.with(|hook| { + if let Some(hook) = hook.borrow_mut().as_mut() { + hook(phase); + } + }); + let _ = phase; + check_attach_budget(deadline, cancellation) +} + +#[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 +4114,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..4e4f932a 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,383 @@ 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 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()); + assert_eq!( + process_loop_decision(true, false, Some(now), now), + ProcessLoopDecision::Timeout + ); + assert_eq!( + process_loop_decision(true, false, Some(now), now + Duration::from_secs(1)), + ProcessLoopDecision::Timeout + ); +} + +#[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()); + } +} + +#[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 now = Instant::now(); + ATTACH_TEST_HOOK.with(|hook| { + *hook.borrow_mut() = Some(Box::new(move |phase| { + if phase == "after_sandbox_verification" { + observed.set(true); + ATTACH_TEST_NOW.with(|clock| clock.set(Some(now + 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 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(); + let thread = thread::spawn(move || { + let deadline = Instant::now() + Duration::from_secs(2); + while !child_pid_file.exists() && Instant::now() < deadline { + thread::sleep(POLL_INTERVAL); + } + assert!(child_pid_file.exists(), "control child must start"); + if cancel { + signal.cancel(); + } + }); + 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(), + Some(Instant::now() + Duration::from_millis(500)), + &cancellation, + ) + .unwrap_err(); + thread.join().unwrap(); + 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; + 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(), + Some(Instant::now() + Duration::from_secs(1)), + &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..be71daf7 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,18 @@ 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.with_context(|| format!("bounded-status main timing: {summary}")) } fn enter_bounded_status_process_scope( @@ -175,6 +188,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 +203,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 +242,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 +255,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 +270,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 +296,21 @@ where AtomicStateWriter::write_direct(&info_root, "exclude", exclude)?; } ensure_worktree_status_deadline(deadline, "after bounded-status Git root setup")?; + 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")?; + timings.enter("callback", worktree_status_now()); after_index_snapshot(&runtime_root)?; ensure_worktree_status_deadline(deadline, "after bounded-status setup callback")?; + timings.enter("head_staging", worktree_status_now()); AtomicStateWriter::write_direct(&git_root, "HEAD", &head)?; 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 +322,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 +339,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 +356,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 +373,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 +399,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 +436,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 +447,28 @@ 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.with_context(|| 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 +499,16 @@ 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:#}" ))), - } + }; + finished.with_context(|| format!("bounded-status cleanup: elapsed_ms={} completed={cleanup_completed}", cleanup_elapsed.as_millis())) } fn validate_bounded_head(bytes: &[u8]) -> Result<()> { @@ -1599,8 +1668,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 +1718,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 +1730,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 +1740,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 +1768,7 @@ fn run_bounded_git_records( let stderr = output.stderr.summarize_chars(512); bail!("worktree status command failed: {}", stderr.text); } + 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 +1777,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..c33f0ff7 100644 --- a/src/worktree/tests_part2.rs +++ b/src/worktree/tests_part2.rs @@ -1615,6 +1615,58 @@ #[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 mut timings = crate::process_runner::PhaseTimings::new(worktree_status_now(), Some(deadline), Duration::from_secs(60), Duration::ZERO, "index_staging"); + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started + Duration::from_secs(25)))); + timings.enter("callback", worktree_status_now()); + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started + Duration::from_secs(59)))); + timings.enter("head_staging", worktree_status_now()); + WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(deadline + Duration::from_secs(1)))); + let failure = ensure_worktree_status_deadline(deadline, "after bounded-status HEAD staging"); + let message = format!("{:#}", diagnose_bounded_status_result(failure, &timings).unwrap_err()); + 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_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 = format!("{error:#}"); + 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) { @@ -1661,6 +1713,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); } From ce1a82ee0f3aaa2111bdb6ca2fafe8a09d692013 Mon Sep 17 00:00:00 2001 From: Meta-Develop <116134763+Meta-Develop@users.noreply.github.com> Date: Sat, 24 Oct 2026 07:01:42 +0900 Subject: [PATCH 2/8] Address attach timing review findings --- src/process_runner.rs | 16 ++- src/process_runner/part2.rs | 8 +- src/process_runner/part3.rs | 48 ++++++- src/process_runner/tests.rs | 243 ++++++++++++++++++++++++++++++++---- src/worktree/part4.rs | 23 ++++ src/worktree/tests_part2.rs | 67 ++++++++-- 6 files changed, 368 insertions(+), 37 deletions(-) diff --git a/src/process_runner.rs b/src/process_runner.rs index 4c15c614..28373f81 100644 --- a/src/process_runner.rs +++ b/src/process_runner.rs @@ -3845,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, @@ -3866,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 { @@ -4054,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, diff --git a/src/process_runner/part2.rs b/src/process_runner/part2.rs index 23b3ef23..78183b26 100644 --- a/src/process_runner/part2.rs +++ b/src/process_runner/part2.rs @@ -906,6 +906,12 @@ impl PreparedProcessTree { unit.launcher_spawned = true; 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!( @@ -928,7 +934,7 @@ impl PreparedProcessTree { ), side_effects: self.side_effects, process_error: Some(format!( - "{label} was cancelled by its run supervisor; {source}" + "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 f00ddd17..e34cf0fc 100644 --- a/src/process_runner/part3.rs +++ b/src/process_runner/part3.rs @@ -965,6 +965,8 @@ impl SystemdUnit { 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); @@ -1099,7 +1101,7 @@ impl SystemdUnit { timings: &mut PhaseTimings, ) -> std::io::Result<()> { loop { - check_attach_budget(deadline, cancellation)?; + self.check_attach_launcher_budget(child, deadline, cancellation)?; if matches!(cgroup_populated(&self.cgroup_path)?, Some(true)) { self.observed_owned = true; } @@ -1169,7 +1171,7 @@ impl SystemdUnit { } } if self.environment_published && !self.environment_released { - check_attach_budget(deadline, cancellation)?; + 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(()) => { @@ -1180,7 +1182,7 @@ impl SystemdUnit { Err(error) => return Err(error), } } - check_attach_budget(deadline, cancellation)?; + 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 { timings.enter("sandbox_verification", Instant::now()); @@ -1219,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 => { @@ -1784,7 +1810,14 @@ fn run_control_command_capture_bounded_until( let status = loop { let backlog = drainers.drain_ready(); 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)); @@ -2372,13 +2405,18 @@ fn attach_now() -> Instant { #[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); } }); - let _ = phase; - check_attach_budget(deadline, cancellation) } #[cfg(all(test, target_os = "linux"))] diff --git a/src/process_runner/tests.rs b/src/process_runner/tests.rs index 4e4f932a..b5280b10 100644 --- a/src/process_runner/tests.rs +++ b/src/process_runner/tests.rs @@ -5770,6 +5770,175 @@ fn phase_diagnostics_preserve_typed_environment_and_io_causes() { 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() { @@ -5829,14 +5998,27 @@ fn bounded_git_absolute_deadline_caps_relative_command_timeout() { assert!(matches!(error, ProcessRunError::SetupTimeout { .. })); assert!(error.to_string().contains("phase=preflight")); assert!(!marker.exists()); - assert_eq!( - process_loop_decision(true, false, Some(now), now), - ProcessLoopDecision::Timeout - ); - assert_eq!( - process_loop_decision(true, false, Some(now), now + Duration::from_secs(1)), - ProcessLoopDecision::Timeout + // 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")] @@ -5847,6 +6029,7 @@ 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()); } } @@ -5858,12 +6041,17 @@ fn systemd_attach_delayed_ready_retains_full_ownership_and_sandbox_proof() { let marker = temp.path().join("target-ran"); let advanced = std::rc::Rc::new(std::cell::Cell::new(false)); let observed = advanced.clone(); - let now = Instant::now(); + let mut selected_at = None; ATTACH_TEST_HOOK.with(|hook| { *hook.borrow_mut() = Some(Box::new(move |phase| { - if phase == "after_sandbox_verification" { + 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); - ATTACH_TEST_NOW.with(|clock| clock.set(Some(now + Duration::from_secs(4)))); + let base = selected_at.expect("capture the deadline-selection clock"); + ATTACH_TEST_NOW.with(|clock| clock.set(Some(base + Duration::from_secs(4)))); } })) }); @@ -5996,21 +6184,32 @@ fn systemd_attach_cancel_or_expire_after_verification_never_releases_target() { 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(); - let thread = thread::spawn(move || { - let deadline = Instant::now() + Duration::from_secs(2); - while !child_pid_file.exists() && Instant::now() < deadline { - thread::sleep(POLL_INTERVAL); - } - assert!(child_pid_file.exists(), "control child must start"); - if cancel { - signal.cancel(); - } + 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"), @@ -6024,11 +6223,10 @@ fn sandbox_property_probe_obeys_attach_deadline_and_cancellation() { &args, "bounded property fixture", temp.path(), - Some(Instant::now() + Duration::from_millis(500)), + None, &cancellation, ) .unwrap_err(); - thread.join().unwrap(); assert_eq!( error.kind(), if cancel { @@ -6060,6 +6258,7 @@ fn sandbox_property_probe_obeys_attach_deadline_and_cancellation() { 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)); @@ -6083,7 +6282,7 @@ fn sandbox_property_probe_obeys_attach_deadline_and_cancellation() { &[], "late property success", temp.path(), - Some(Instant::now() + Duration::from_secs(1)), + None, &cancellation, ) .unwrap_err(); diff --git a/src/worktree/part4.rs b/src/worktree/part4.rs index be71daf7..3f16ea81 100644 --- a/src/worktree/part4.rs +++ b/src/worktree/part4.rs @@ -296,16 +296,24 @@ 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())?; @@ -1340,8 +1348,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) }; @@ -1768,6 +1789,8 @@ 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]) { diff --git a/src/worktree/tests_part2.rs b/src/worktree/tests_part2.rs index c33f0ff7..24424660 100644 --- a/src/worktree/tests_part2.rs +++ b/src/worktree/tests_part2.rs @@ -1622,19 +1622,69 @@ let started = Instant::now(); let deadline = started + Duration::from_secs(60); WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started))); - let mut timings = crate::process_runner::PhaseTimings::new(worktree_status_now(), Some(deadline), Duration::from_secs(60), Duration::ZERO, "index_staging"); - WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started + Duration::from_secs(25)))); - timings.enter("callback", worktree_status_now()); - WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(started + Duration::from_secs(59)))); - timings.enter("head_staging", worktree_status_now()); - WORKTREE_STATUS_TEST_CLOCK.with(|clock| clock.set(Some(deadline + Duration::from_secs(1)))); - let failure = ensure_worktree_status_deadline(deadline, "after bounded-status HEAD staging"); - let message = format!("{:#}", diagnose_bounded_status_result(failure, &timings).unwrap_err()); + 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); + } + #[cfg(target_os = "linux")] #[test] fn bounded_status_failure_diagnostics_exclude_queue_and_separate_cleanup() { @@ -1671,6 +1721,7 @@ 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()); } } From b9ff8d677b26fbc3d67668f69ee29485107b114d Mon Sep 17 00:00:00 2001 From: Meta-Develop <116134763+Meta-Develop@users.noreply.github.com> Date: Sat, 24 Oct 2026 07:57:53 +0900 Subject: [PATCH 3/8] Pin Linux integration tests to ubuntu-24.04 --- .github/workflows/ci.yml | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index f066d8a1..2ed16774 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -297,7 +297,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 From 562a4b280ea2051ed3f90ea2e662c3b4711de4da Mon Sep 17 00:00:00 2001 From: Meta-Develop <116134763+Meta-Develop@users.noreply.github.com> Date: Sat, 24 Oct 2026 09:11:30 +0900 Subject: [PATCH 4/8] Keep original bounded-status error text ahead of phase diagnostics --- src/worktree/part4.rs | 24 ++++++++++++++++++++---- src/worktree/tests_part2.rs | 27 ++++++++++++++++++++++++++- 2 files changed, 46 insertions(+), 5 deletions(-) diff --git a/src/worktree/part4.rs b/src/worktree/part4.rs index 3f16ea81..4039efe4 100644 --- a/src/worktree/part4.rs +++ b/src/worktree/part4.rs @@ -114,7 +114,19 @@ fn bounded_worktree_records_mode( 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.with_context(|| format!("bounded-status main timing: {summary}")) + 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. + let message = format!("{error}; {diagnostics}"); + error.context(message) } fn enter_bounded_status_process_scope( @@ -476,7 +488,9 @@ where ); 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.with_context(|| format!("bounded-status final verification: lock_elapsed_ms={} repository_elapsed_ms={}", lock_elapsed.as_millis(), repository_elapsed.as_millis())) + 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 @@ -512,11 +526,13 @@ fn finish_bounded_status_runtime( (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!( + (Err(error), Err(cleanup_error)) => Err(append_bounded_status_diagnostics(error, format!( "bounded-status runtime cleanup also failed: {cleanup_error:#}" ))), }; - finished.with_context(|| format!("bounded-status cleanup: elapsed_ms={} completed={cleanup_completed}", cleanup_elapsed.as_millis())) + 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<()> { diff --git a/src/worktree/tests_part2.rs b/src/worktree/tests_part2.rs index 24424660..25171b01 100644 --- a/src/worktree/tests_part2.rs +++ b/src/worktree/tests_part2.rs @@ -1685,6 +1685,30 @@ 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_failure_diagnostics_exclude_queue_and_separate_cleanup() { @@ -1708,7 +1732,8 @@ 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 = format!("{error:#}"); + 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}"); } From ae5c8e04ea269356fd247bcf784a4b28bac372e4 Mon Sep 17 00:00:00 2001 From: Meta-Develop <116134763+Meta-Develop@users.noreply.github.com> Date: Sat, 24 Oct 2026 09:34:58 +0900 Subject: [PATCH 5/8] Redact secondary errors on bounded-status both-fail paths --- src/worktree/part4.rs | 22 ++++++---- src/worktree/tests_part2.rs | 85 +++++++++++++++++++++++++++++++++++++ 2 files changed, 98 insertions(+), 9 deletions(-) diff --git a/src/worktree/part4.rs b/src/worktree/part4.rs index 4039efe4..ce730b49 100644 --- a/src/worktree/part4.rs +++ b/src/worktree/part4.rs @@ -125,6 +125,7 @@ fn append_bounded_status_diagnostics( ) -> 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) } @@ -526,9 +527,10 @@ fn finish_bounded_status_runtime( (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(append_bounded_status_diagnostics(error, format!( - "bounded-status runtime cleanup also failed: {cleanup_error:#}" - ))), + (Err(error), Err(_)) => Err(append_bounded_status_diagnostics( + error, + "bounded-status runtime cleanup also failed: ", + )), }; finished.map_err(|error| { append_bounded_status_diagnostics(error, format!("bounded-status cleanup: elapsed_ms={} completed={cleanup_completed}", cleanup_elapsed.as_millis())) @@ -588,9 +590,10 @@ 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(_)) => Err(append_bounded_status_diagnostics( + error, + "operation also lost its repository pathname binding: ", + )), } } @@ -1305,9 +1308,10 @@ 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(_)) => Err(append_bounded_status_diagnostics( + error, + "operation also lost its bounded-status lock-path binding: ", + )), } } diff --git a/src/worktree/tests_part2.rs b/src/worktree/tests_part2.rs index 25171b01..dd7da206 100644 --- a/src/worktree/tests_part2.rs +++ b/src/worktree/tests_part2.rs @@ -1709,6 +1709,91 @@ 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 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!("binding disappeared: {private_path}") + .context(format!("verification failed at {private_path}")) + }; + let results = [ + ( + "runtime cleanup also failed", + finish_bounded_status_runtime::<()>(Err(operation_error()), &root, &lock) + .map(|_| ()), + ), + ( + "repository pathname binding", + finish_with_repository_binding_verification::<()>( + Err(operation_error()), + Err(binding_error()), + ), + ), + ( + "bounded-status lock-path binding", + finish_with_status_lock_verification::<()>( + Err(operation_error()), + Err(binding_error()), + ), + ), + ]; + for (secondary, 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}"); + 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() { From 0ed4475a1e9456f2e651dc12c1ed1345c867d757 Mon Sep 17 00:00:00 2001 From: Meta-Develop <116134763+Meta-Develop@users.noreply.github.com> Date: Sat, 24 Oct 2026 10:05:28 +0900 Subject: [PATCH 6/8] Keep static cleanup classifications in redacted both-fail summaries --- src/worktree/part4.rs | 91 ++++++++++++++++++++++++++++++++++--- src/worktree/tests_part2.rs | 44 ++++++++++++++++-- 2 files changed, 126 insertions(+), 9 deletions(-) diff --git a/src/worktree/part4.rs b/src/worktree/part4.rs index ce730b49..f3476314 100644 --- a/src/worktree/part4.rs +++ b/src/worktree/part4.rs @@ -130,6 +130,76 @@ fn append_bounded_status_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( timeout: Duration, ) -> Result<(std::sync::MutexGuard<'static, ()>, Instant, Duration)> { @@ -527,9 +597,12 @@ fn finish_bounded_status_runtime( (Ok(value), Ok(_)) => Ok((value, cleanup_elapsed)), (Err(error), Ok(_)) => Err(error), (Ok(_), Err(cleanup_error)) => Err(cleanup_error), - (Err(error), Err(_)) => Err(append_bounded_status_diagnostics( + (Err(error), Err(cleanup_error)) => Err(append_bounded_status_diagnostics( error, - "bounded-status runtime cleanup also failed: ", + format!( + "bounded-status runtime cleanup also failed: {}", + redacted_bounded_status_secondary(&cleanup_error, "cleanup") + ), )), }; finished.map_err(|error| { @@ -590,9 +663,12 @@ 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(_)) => Err(append_bounded_status_diagnostics( + (Err(error), Err(binding_error)) => Err(append_bounded_status_diagnostics( error, - "operation also lost its repository pathname binding: ", + format!( + "operation also lost its repository pathname binding: {}", + redacted_bounded_status_secondary(&binding_error, "binding") + ), )), } } @@ -1308,9 +1384,12 @@ 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(_)) => Err(append_bounded_status_diagnostics( + (Err(error), Err(lock_error)) => Err(append_bounded_status_diagnostics( error, - "operation also lost its bounded-status lock-path binding: ", + format!( + "operation also lost its bounded-status lock-path binding: {}", + redacted_bounded_status_secondary(&lock_error, "lock") + ), )), } } diff --git a/src/worktree/tests_part2.rs b/src/worktree/tests_part2.rs index dd7da206..c0c66137 100644 --- a/src/worktree/tests_part2.rs +++ b/src/worktree/tests_part2.rs @@ -1728,6 +1728,13 @@ 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( @@ -1737,17 +1744,22 @@ .context("original classified failure") }; let binding_error = || { - anyhow::anyhow!("binding disappeared: {private_path}") + 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()), @@ -1755,13 +1767,26 @@ ), ( "bounded-status lock-path binding", + &["kernel state lock path does not name its opened descriptor"][..], finish_with_status_lock_verification::<()>( Err(operation_error()), - Err(binding_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, result) in results { + for (secondary, classifications, result) in results { let started = Instant::now(); let timings = crate::process_runner::PhaseTimings::new( started, @@ -1777,6 +1802,19 @@ "{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(" Date: Sat, 24 Oct 2026 10:05:30 +0900 Subject: [PATCH 7/8] Pin Linux library tests to ubuntu-24.04 --- .github/workflows/ci.yml | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 2ed16774..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 From ce268df72c05197733fd3668ba0a9b0f8b0f2eb5 Mon Sep 17 00:00:00 2001 From: Meta-Develop <116134763+Meta-Develop@users.noreply.github.com> Date: Sat, 24 Oct 2026 10:13:17 +0900 Subject: [PATCH 8/8] Update ctutils 0.4.4 and tokio 1.53.3 for RUSTSEC-2026-0385/0386 --- Cargo.lock | 8 ++++---- account-manager/src-tauri/Cargo.lock | 8 ++++---- 2 files changed, 8 insertions(+), 8 deletions(-) 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",