use std::{
collections::{BTreeMap, VecDeque},
io::Write as _,
sync::{
atomic::{AtomicBool, Ordering},
Arc, Mutex,
},
time::{Duration, Instant},
};
use tokio::sync::{
mpsc::{unbounded_channel, UnboundedReceiver, UnboundedSender},
watch,
};
use crate::{
bindings::host::murmur::tool::run::{Status, ToolResult},
cancel::CancelSignal,
origin::{TaskOrigin, TaskProvenance},
};
pub const WORK_ID_PREFIX: &str = "wrk_";
pub fn new_work_id() -> String {
format!("{WORK_ID_PREFIX}{}", uuid::Uuid::now_v7().simple())
}
#[derive(Debug, Clone, PartialEq, Eq)]
pub(crate) struct OutputLog {
pub relative: String,
pub path: String,
}
pub(crate) fn output_path_for(
records_root: &crate::workdir_fs::WorkdirRoot,
stem: &str,
) -> OutputLog {
let relative = format!("logs/{stem}.log");
let path = records_root
.host_path(&relative)
.to_string_lossy()
.into_owned();
OutputLog { relative, path }
}
#[derive(Debug, Clone)]
pub(crate) struct DetachedWork {
pub work_id: String,
pub binary: String,
pub command: String,
pub started_at_ms: u64,
}
#[derive(Debug, Clone)]
pub(crate) struct DetachedCompletion {
pub work_id: String,
pub binary: String,
pub command: String,
pub exit_code: i32,
pub duration_ms: u64,
pub output_path: String,
pub output_bytes: u64,
pub resource_limit: Option<String>,
pub output_holders: crate::shell::OutputHolders,
pub context_id: String,
pub provenance: TaskProvenance,
pub error: Option<String>,
}
impl DetachedCompletion {
pub(crate) fn message_text(&self) -> String {
let mut text = format!(
"Background shell command finished.\n\
work_id: {}\n\
binary: {}\n\
command: {}\n\
status: {}\n\
exit_code: {}\n\
duration_ms: {}\n\
output: {} ({} bytes)",
self.work_id,
self.binary,
self.command,
self.status(),
self.exit_code,
self.duration_ms,
self.output_path,
self.output_bytes,
);
if let Some(limit) = &self.resource_limit {
text.push('\n');
text.push_str(&crate::resources::resource_limit_line(limit));
}
if let Some(note) = self.output_holders.note() {
text.push('\n');
text.push_str(¬e);
}
if let Some(error) = &self.error {
text.push_str(&format!("\nwait_error: {error}"));
}
text.push_str(
"\n\nThe full stdout and stderr are in that file and are not reproduced here.",
);
text
}
pub(crate) fn status(&self) -> &'static str {
if self.exit_code == 0 && self.error.is_none() && self.resource_limit.is_none() {
"ok"
} else {
"error"
}
}
}
#[derive(Debug, Clone)]
pub(crate) struct DetachedDispatchInfo {
pub work_id: String,
pub binary: String,
pub command: String,
pub grace_ms: u64,
}
pub(crate) fn demotion_tool_result(work_id: &str, delivered: bool) -> ToolResult {
let mut data = format!(
"The command is still running and was moved to the background as {work_id}. The \
{tool} tool reports on it, waits for it or stops it by that id. A command still running \
when the session ends is killed.",
tool = crate::background_command::BACKGROUND_COMMAND_TOOL,
);
if delivered {
data.push_str(&format!(
" If it exits before {tool} has reported its exit, its result also arrives later as a \
separate task.",
tool = crate::background_command::BACKGROUND_COMMAND_TOOL,
));
}
ToolResult {
status: Status::Passed,
summary: Some(format!(
"Command still running in the background as {work_id}."
)),
data: Some(data),
data_path: None,
truncated: false,
metadata: vec![("work_id".to_string(), work_id.to_string())],
}
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)]
pub(crate) enum Phase {
Running,
LeaderExited,
Finished,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub(crate) enum CommandState {
Running,
Exited,
Stopped,
}
impl CommandState {
pub(crate) fn as_str(self) -> &'static str {
match self {
Self::Running => "running",
Self::Exited => "exited",
Self::Stopped => "stopped",
}
}
}
pub(crate) struct LiveOutput {
file: Option<std::fs::File>,
tail: VecDeque<u8>,
section_bytes: u64,
write_error: Option<String>,
}
impl LiveOutput {
pub(crate) fn open(
records_root: &crate::workdir_fs::WorkdirRoot,
relative: &str,
command_line: &str,
) -> Self {
let mut live = Self {
file: None,
tail: VecDeque::new(),
section_bytes: 0,
write_error: None,
};
match records_root.open_append(relative, crate::workdir_fs::DEFAULT_FILE_MODE) {
Ok(file) => {
live.file = Some(file);
live.write(format!("Command: {command_line}\n\n").as_bytes());
}
Err(error) => live.write_error = Some(format!("failed to write shell log: {error}")),
}
live
}
fn write(&mut self, bytes: &[u8]) {
let Some(file) = self.file.as_mut() else {
return;
};
if let Err(error) = file.write_all(bytes) {
self.file = None;
self.write_error
.get_or_insert_with(|| format!("failed to write shell log: {error}"));
}
}
pub(crate) fn append(&mut self, bytes: &[u8]) {
self.write(bytes);
self.section_bytes = self.section_bytes.saturating_add(bytes.len() as u64);
let keep = crate::shell::MAX_SHELL_OUTPUT_BYTES;
if bytes.len() >= keep {
self.tail.clear();
self.tail.extend(&bytes[bytes.len() - keep..]);
} else {
let excess = (self.tail.len() + bytes.len()).saturating_sub(keep);
self.tail.drain(..excess);
self.tail.extend(bytes);
}
}
pub(crate) fn finish(&mut self, exit_code: i32) -> Option<String> {
self.write(format!("\n\nExit code: {exit_code}\n").as_bytes());
self.file = None;
self.write_error.clone()
}
}
struct DetachedEntry {
work: DetachedWork,
started: Instant,
pgid: i32,
output_path: String,
output: Arc<Mutex<LiveOutput>>,
leader_running: bool,
stop_requested: bool,
signals_sent: u32,
finished: Option<DetachedCompletion>,
exit_reported: bool,
phase: watch::Sender<Phase>,
}
#[derive(Debug, Clone)]
pub(crate) struct CommandSnapshot {
pub work_id: String,
pub binary: String,
pub command: String,
pub state: CommandState,
pub elapsed_ms: u64,
pub finished: Option<DetachedCompletion>,
pub output_path: String,
pub output_bytes: u64,
pub tail: Vec<u8>,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub(crate) enum WaitEnd {
Finished,
TimedOut,
Canceled,
Unknown,
}
pub(crate) struct DetachedRegistry {
entries: Mutex<BTreeMap<String, DetachedEntry>>,
reports: UnboundedSender<DetachedReport>,
}
impl DetachedRegistry {
pub(crate) fn new() -> (Arc<Self>, UnboundedReceiver<DetachedReport>) {
let (reports, receiver) = unbounded_channel();
(
Arc::new(Self {
entries: Mutex::new(BTreeMap::new()),
reports,
}),
receiver,
)
}
fn lock(&self) -> std::sync::MutexGuard<'_, BTreeMap<String, DetachedEntry>> {
self.entries.lock().expect("detached registry mutex")
}
pub(crate) fn report(&self, report: DetachedReport) {
let _ = self.reports.send(report);
}
pub(crate) fn register(
&self,
work: DetachedWork,
started: Instant,
pgid: i32,
output_path: String,
output: Arc<Mutex<LiveOutput>>,
) {
let (phase, _) = watch::channel(Phase::Running);
self.lock().insert(
work.work_id.clone(),
DetachedEntry {
work,
started,
pgid,
output_path,
output,
leader_running: true,
stop_requested: false,
signals_sent: 0,
finished: None,
exit_reported: false,
phase,
},
);
}
pub(crate) fn leader_exited(&self, work_id: &str) {
if let Some(entry) = self.lock().get_mut(work_id) {
entry.leader_running = false;
entry.phase.send_replace(Phase::LeaderExited);
}
}
pub(crate) fn complete(&self, mut completion: DetachedCompletion) {
{
let mut entries = self.lock();
if let Some(entry) = entries.get_mut(&completion.work_id) {
if entry.stop_requested {
completion.resource_limit = None;
}
entry.leader_running = false;
entry.finished = Some(completion.clone());
entry.phase.send_replace(Phase::Finished);
}
}
self.report(DetachedReport::Completed(completion));
}
pub(crate) fn outstanding(&self) -> Vec<DetachedWork> {
self.lock()
.values()
.filter(|entry| entry.finished.is_none())
.map(|entry| entry.work.clone())
.collect()
}
pub(crate) fn read(&self, work_id: &str) -> Option<CommandSnapshot> {
let mut entries = self.lock();
let entry = entries.get_mut(work_id)?;
if entry.finished.is_some() {
entry.exit_reported = true;
}
let state = match (&entry.finished, entry.stop_requested) {
(None, _) => CommandState::Running,
(Some(_), false) => CommandState::Exited,
(Some(_), true) => CommandState::Stopped,
};
let elapsed_ms = match &entry.finished {
Some(completion) => completion.duration_ms,
None => millis(entry.started.elapsed()),
};
let (output_bytes, tail) = {
let output = entry
.output
.lock()
.unwrap_or_else(std::sync::PoisonError::into_inner);
(output.section_bytes, output.tail.iter().copied().collect())
};
Some(CommandSnapshot {
work_id: entry.work.work_id.clone(),
binary: entry.work.binary.clone(),
command: entry.work.command.clone(),
state,
elapsed_ms,
finished: entry.finished.clone(),
output_path: entry.output_path.clone(),
output_bytes,
tail,
})
}
pub(crate) fn exit_reported(&self, work_id: &str) -> bool {
self.lock()
.get(work_id)
.is_some_and(|entry| entry.exit_reported)
}
fn phase(&self, work_id: &str) -> Option<watch::Receiver<Phase>> {
self.lock()
.get(work_id)
.map(|entry| entry.phase.subscribe())
}
fn signal_stop(&self, work_id: &str, signal: libc::c_int) -> bool {
let mut entries = self.lock();
let Some(entry) = entries
.get_mut(work_id)
.filter(|entry| entry.leader_running)
else {
return false;
};
let sent = crate::formation_launch::signal_group(i64::from(entry.pgid), signal);
if sent {
entry.signals_sent += 1;
entry.stop_requested = true;
}
sent
}
pub(crate) fn kill_running(&self) {
for entry in self.lock().values_mut() {
if entry.leader_running
&& crate::formation_launch::signal_group(i64::from(entry.pgid), libc::SIGKILL)
{
entry.signals_sent += 1;
}
}
}
pub(crate) async fn wait(
&self,
work_id: &str,
bound: Duration,
cancel: Option<&crate::cancel::CancelSignal>,
) -> WaitEnd {
let Some(mut phase) = self.phase(work_id) else {
return WaitEnd::Unknown;
};
let canceled = async {
match cancel {
Some(signal) => signal.canceled().await,
None => std::future::pending().await,
}
};
tokio::select! {
finished = phase.wait_for(|phase| *phase == Phase::Finished) => {
if finished.is_ok() { WaitEnd::Finished } else { WaitEnd::TimedOut }
}
() = tokio::time::sleep(bound) => WaitEnd::TimedOut,
() = canceled => WaitEnd::Canceled,
}
}
pub(crate) async fn stop(&self, work_id: &str) -> bool {
let Some(mut phase) = self.phase(work_id) else {
return false;
};
if self.signal_stop(work_id, libc::SIGTERM) {
let exited = tokio::time::timeout(
crate::background_command::STOP_TERM_GRACE,
phase.wait_for(|phase| *phase >= Phase::LeaderExited),
)
.await;
if !matches!(exited, Ok(Ok(_))) {
self.signal_stop(work_id, libc::SIGKILL);
}
}
let _ = tokio::time::timeout(
crate::background_command::STOP_KILL_WAIT,
phase.wait_for(|phase| *phase == Phase::Finished),
)
.await;
true
}
#[cfg(test)]
pub(crate) fn signals_sent(&self, work_id: &str) -> u32 {
self.lock()
.get(work_id)
.map_or(0, |entry| entry.signals_sent)
}
}
fn millis(duration: Duration) -> u64 {
duration.as_millis().try_into().unwrap_or(u64::MAX)
}
#[cfg(test)]
pub(crate) struct KillRunningOnDrop(pub(crate) Arc<DetachedRegistry>);
#[cfg(test)]
impl Drop for KillRunningOnDrop {
fn drop(&mut self) {
self.0.kill_running();
}
}
pub(crate) struct DetachPolicy {
pub grace: Duration,
pub delivered: bool,
pub registry: Arc<DetachedRegistry>,
pub command: String,
pub context_id: String,
pub provenance: Option<TaskProvenance>,
pub abandoned: Option<AbandonSignal>,
pub canceled: Option<CancelSignal>,
}
#[derive(Debug, Clone, Default)]
pub(crate) struct AbandonSignal(Arc<AtomicBool>);
impl AbandonSignal {
pub(crate) fn new() -> Self {
Self::default()
}
pub(crate) fn raise(&self) {
self.0.store(true, Ordering::SeqCst);
}
pub(crate) fn is_raised(&self) -> bool {
self.0.load(Ordering::SeqCst)
}
}
impl DetachPolicy {
pub(crate) fn completion_provenance(&self) -> TaskProvenance {
TaskProvenance::derive(
TaskOrigin::Completion,
self.provenance.map(|task| task.trust()),
)
}
}
#[derive(Debug, Clone)]
pub(crate) enum AbandonedDisposition {
StillRunning {
running_ms: u64,
},
FinishedTooLate {
exit_code: i32,
duration_ms: u64,
output_path: String,
output_bytes: u64,
resource_limit: Option<String>,
wait_error: Option<String>,
status: &'static str,
},
}
#[derive(Debug, Clone)]
pub(crate) struct AbandonedWork {
pub work_id: String,
pub binary: String,
pub command: String,
pub disposition: AbandonedDisposition,
}
impl AbandonedWork {
pub(crate) fn running_ms(&self) -> u64 {
match &self.disposition {
AbandonedDisposition::StillRunning { running_ms } => *running_ms,
AbandonedDisposition::FinishedTooLate { duration_ms, .. } => *duration_ms,
}
}
pub(crate) fn recovered(&self) -> Option<(i32, &str, u64)> {
match &self.disposition {
AbandonedDisposition::StillRunning { .. } => None,
AbandonedDisposition::FinishedTooLate {
exit_code,
output_path,
output_bytes,
..
} => Some((*exit_code, output_path.as_str(), *output_bytes)),
}
}
}
pub(crate) fn abandonment_report_text(
session_id: &str,
records_root: &crate::workdir_fs::WorkdirRoot,
abandoned: &[AbandonedWork],
) -> String {
let count = abandoned.len();
let plural = if count == 1 { "command" } else { "commands" };
let mut text = format!(
"[capsule-runtime] {count} background shell {plural} discarded at session end.\n\n\
Session {session_id} ended while {count} demoted shell {plural} {} unaccounted for. \
Every process the session started was killed when it ended; what is known about each \
command is below.\n",
if count == 1 { "was" } else { "were" }
);
for work in abandoned {
text.push_str(&format!(
"\nwork_id: {}\nbinary: {}\ncommand: {}\n",
work.work_id, work.binary, work.command
));
match &work.disposition {
AbandonedDisposition::StillRunning { running_ms } => {
text.push_str(&format!(
"state: killed at session end after {running_ms} ms\n\
result: none — it was killed before it finished, so no task carries an exit \
code. What it printed before the kill is in {}.\n",
output_path_for(records_root, &work.work_id).path
));
}
AbandonedDisposition::FinishedTooLate {
exit_code,
duration_ms,
output_path,
output_bytes,
resource_limit,
wait_error,
status,
} => {
text.push_str(&format!(
"state: finished during teardown after {duration_ms} ms\n\
status: {status}\n\
exit_code: {exit_code}\n"
));
if let Some(limit) = resource_limit {
text.push_str(&format!("resource_limit: {limit}\n"));
}
if let Some(error) = wait_error {
text.push_str(&format!("wait_error: {error}\n"));
}
text.push_str(&format!(
"output: {output_path} ({output_bytes} bytes)\n\
result: on disk — it finished too late for any task to carry it back to the \
agent.\n"
));
}
}
}
text.push_str(
"\nA session's end kills every command it demoted and every process its shell calls \
started in the background. Declare lifecycle.task_acceptance: queue with \
lifecycle.after_task: sleep for a session that outlives its task and can be told the \
result instead.",
);
text
}
#[derive(Debug, Clone)]
pub(crate) struct LostWork {
pub work_id: String,
pub binary: String,
pub command: String,
pub detached_at_ms: u64,
}
#[derive(Debug, Clone)]
pub(crate) struct LostReport {
pub started_in_session: String,
pub lost: Vec<LostWork>,
pub context_id: String,
pub provenance: TaskProvenance,
pub task_id: String,
}
impl LostReport {
pub(crate) fn message_text(&self) -> String {
let mut text = format!(
"Background shell commands from an earlier session were never accounted for.\n\
\n\
Session {} ended without recording what became of the commands below; they were \
running in the background at the time. No exit code was recorded for any of them, \
and whether each command finished at all is unknown.\n",
self.started_in_session
);
for work in &self.lost {
text.push_str(&format!(
"\nwork_id: {}\nbinary: {}\ncommand: {}\ndetached_at_ms: {}\n",
work.work_id, work.binary, work.command, work.detached_at_ms
));
}
text.push_str(
"\nNone of these is known to have succeeded and none is known to have failed. Treat \
each as unknown, and start the work again only if it still matters.",
);
text
}
}
#[derive(Debug, Clone)]
pub(crate) enum DetachedReport {
Completed(DetachedCompletion),
Lost(LostReport),
}
#[cfg(test)]
mod tests {
use super::*;
use std::{
path::{Path, PathBuf},
time::{Duration, Instant},
};
use crate::{
origin::TrustClass,
sandbox::ShellEnforcement,
shell::{
run_shell,
test_support::{process_dead_within, read_pid, KillPidFileOnDrop},
ShellOutcome,
},
types::CapabilityPolicy,
};
fn bash_policy() -> CapabilityPolicy {
CapabilityPolicy {
shell_allow: vec!["bash".to_string()],
..Default::default()
}
}
fn records_dir(base: &Path) -> PathBuf {
base.join(crate::records_dir::RECORDS_DIR_NAME)
}
fn detached_run(
workdir: &Path,
runtime_base: &Path,
script: &str,
grace: Duration,
) -> (
ShellOutcome,
Arc<DetachedRegistry>,
UnboundedReceiver<DetachedReport>,
) {
detached_run_with(
workdir,
&ShellEnforcement::environment_only()
.with_runtime_dir(crate::sandbox::test_runtime_dir(runtime_base), None),
script,
grace,
)
}
fn detached_run_with(
workdir: &Path,
enforcement: &ShellEnforcement,
script: &str,
grace: Duration,
) -> (
ShellOutcome,
Arc<DetachedRegistry>,
UnboundedReceiver<DetachedReport>,
) {
let (registry, receiver) = DetachedRegistry::new();
let outcome = run_shell(
"bash",
&["-c", script],
&[],
&crate::workdir_fs::WorkdirRoot::open(workdir).unwrap(),
&bash_policy(),
enforcement,
Some(DetachPolicy {
grace,
delivered: true,
registry: Arc::clone(®istry),
command: script.to_string(),
context_id: "ctx_detached_tests".to_string(),
provenance: Some(TaskProvenance::derive(TaskOrigin::User, None)),
abandoned: None,
canceled: None,
}),
)
.expect("a declared binary runs");
(outcome, registry, receiver)
}
fn await_completion(receiver: &mut UnboundedReceiver<DetachedReport>) -> DetachedCompletion {
let deadline = Instant::now() + Duration::from_secs(30);
loop {
match receiver.try_recv() {
Ok(DetachedReport::Completed(completion)) => return completion,
Ok(other) => panic!("a shell command's completion was expected; got {other:?}"),
Err(tokio::sync::mpsc::error::TryRecvError::Empty) => {
assert!(
Instant::now() < deadline,
"timed out waiting for the detached completion"
);
std::thread::sleep(Duration::from_millis(25));
}
Err(error) => panic!("the completion channel closed early: {error}"),
}
}
}
fn completion_provenance() -> TaskProvenance {
TaskProvenance::derive(TaskOrigin::Completion, Some(TrustClass::Untrusted))
}
#[test]
fn no_two_completions_share_an_opening_line() {
let outcome = crate::delegation::DelegationOutcome {
delegation_id: "dlg_0001".to_string(),
capsule_name: "worker".to_string(),
capsule_version: "0.1.0".to_string(),
session_id: "ses_child".to_string(),
status: crate::delegation::DelegationStatus::Ok,
result_path: None,
workdir: "/tmp/child".to_string(),
duration_ms: 1,
detail: None,
reported_by: crate::delegation::Reporter::Launcher,
delivered: true,
delivery_error: None,
};
let completion = DetachedCompletion {
work_id: "wrk_0001".to_string(),
binary: "bash".to_string(),
command: "sleep 3".to_string(),
exit_code: 0,
duration_ms: 3_000,
output_path: "/home/test/.murmur/records/work/ses_1/logs/wrk_0001.log".to_string(),
output_bytes: 0,
resource_limit: None,
output_holders: crate::shell::OutputHolders::Closed,
context_id: "ctx_1".to_string(),
provenance: completion_provenance(),
error: None,
};
let texts = [
("delegation outcome", outcome.message_text()),
("detached shell completion", completion.message_text()),
];
for (index, (name, text)) in texts.iter().enumerate() {
let opening = text.lines().next().unwrap_or_default();
assert!(!opening.is_empty(), "{name} opens with nothing");
for (other_name, other) in texts.iter().skip(index + 1) {
assert_ne!(
opening,
other.lines().next().unwrap_or_default(),
"{name} and {other_name} open with the same line"
);
}
}
}
#[test]
fn a_completion_names_its_limit_in_the_shared_wording() {
let completion = DetachedCompletion {
work_id: "wrk_0001".to_string(),
binary: "bash".to_string(),
command: "make -j64".to_string(),
exit_code: 1,
duration_ms: 3_000,
output_path: "/home/test/.murmur/records/work/ses_1/logs/wrk_0001.log".to_string(),
output_bytes: 0,
resource_limit: Some("cgroup_pids_max".into()),
output_holders: crate::shell::OutputHolders::Closed,
context_id: "ctx_1".to_string(),
provenance: completion_provenance(),
error: None,
};
let text = completion.message_text();
let expected = crate::resources::resource_limit_line("cgroup_pids_max");
assert!(
text.lines().any(|line| line == expected),
"no limit line in:\n{text}"
);
assert_eq!(
text.lines().next(),
Some("Background shell command finished.")
);
assert_eq!(completion.status(), "error");
assert!(text.ends_with("are not reproduced here."), "{text}");
}
#[test]
fn a_demoted_command_completes_when_its_background_holders_are_killed() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let _sleeper = KillPidFileOnDrop(workdir.path().join("sleeper.pid"));
let (outcome, _registry, mut receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 2; sleep 300 & echo $! > sleeper.pid; echo started",
Duration::from_secs(1),
);
let ShellOutcome::Detached(info) = outcome else {
panic!("a two-second command must not finish inside a one-second grace: {outcome:?}");
};
let waiting = Instant::now();
let completion = await_completion(&mut receiver);
let waited = waiting.elapsed();
assert!(
waited < Duration::from_secs(15),
"the completion took {waited:?}"
);
assert_eq!(completion.work_id, info.work_id);
assert_eq!(completion.exit_code, 0);
assert_eq!(
completion.output_holders,
crate::shell::OutputHolders::Killed
);
let note = crate::shell::OutputHolders::Killed.note().unwrap();
let text = completion.message_text();
assert!(text.lines().any(|line| line == note), "{text}");
assert!(text.ends_with("are not reproduced here."), "{text}");
let log = std::fs::read_to_string(&completion.output_path).unwrap();
assert!(log.contains("started"), "{log}");
let sleeper = read_pid(&workdir.path().join("sleeper.pid"));
assert!(
process_dead_within(sleeper, Duration::from_secs(2)),
"the background sleeper {sleeper} is still running"
);
}
#[test]
fn a_command_outrunning_the_grace_period_is_demoted() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let started = Instant::now();
let (outcome, registry, mut receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 3; printf 'fin%s' 'ished-marker'",
Duration::from_secs(1),
);
let info = match outcome {
ShellOutcome::Detached(info) => info,
ShellOutcome::Finished(result) => {
panic!(
"a three-second command must not finish inside a one-second grace: {result:?}"
)
}
};
assert!(
started.elapsed() < Duration::from_secs(3),
"the call returned only after the command did"
);
assert!(
info.work_id.starts_with(WORK_ID_PREFIX)
&& info.work_id[WORK_ID_PREFIX.len()..]
.chars()
.all(|c| c.is_ascii_hexdigit() && !c.is_ascii_uppercase()),
"work id {} must match ^wrk_[0-9a-f]+$",
info.work_id
);
assert_eq!(info.grace_ms, 1_000);
assert_eq!(
registry
.outstanding()
.iter()
.map(|work| work.work_id.clone())
.collect::<Vec<_>>(),
vec![info.work_id.clone()],
"the work is registered before the handle is returned"
);
let completion = await_completion(&mut receiver);
assert_eq!(completion.work_id, info.work_id);
assert_eq!(completion.exit_code, 0);
assert_eq!(completion.status(), "ok");
let expected_path = records_dir(runtime.path())
.join("logs")
.join(format!("{}.log", info.work_id));
assert!(expected_path.is_absolute());
assert_eq!(
completion.output_path,
expected_path.to_string_lossy(),
"the completion names <records dir>/logs/<work_id>.log by its absolute path"
);
assert_eq!(completion.provenance.origin(), TaskOrigin::Completion);
assert_eq!(completion.provenance.trust(), TrustClass::Trusted);
assert_eq!(completion.context_id, "ctx_detached_tests");
assert!(
registry.outstanding().is_empty(),
"a completed command is no longer outstanding"
);
let log = std::fs::read_to_string(&completion.output_path)
.expect("the completion's output file exists");
assert!(
log.contains("finished-marker"),
"the output is in the log: {log}"
);
assert_eq!(completion.output_bytes, log.len() as u64);
let text = completion.message_text();
assert!(
!text.contains("finished-marker"),
"the output never reaches the agent: {text}"
);
assert!(
text.contains(&format!(
"output: {} ({} bytes)",
completion.output_path, completion.output_bytes
)),
"{text}"
);
assert!(!text.contains("in the capsule workdir"), "{text}");
assert!(
!workdir.path().join("logs").exists(),
"nothing is written into the accessible workdir"
);
}
#[test]
fn with_no_records_directory_a_slow_command_is_not_demoted() {
let workdir = tempfile::tempdir().unwrap();
let base = tempfile::tempdir().unwrap();
let started = Instant::now();
let (outcome, registry, mut receiver) = detached_run_with(
workdir.path(),
&ShellEnforcement::environment_only().with_runtime_dir(
crate::runtime_dir::RuntimeDirRoots {
records: None,
..crate::sandbox::test_runtime_dir(base.path())
},
None,
),
"sleep 2; echo done",
Duration::from_millis(200),
);
let result = match outcome {
ShellOutcome::Finished(result) => result,
ShellOutcome::Detached(info) => {
panic!(
"no records directory, yet the command was demoted as {}",
info.work_id
)
}
};
assert!(started.elapsed() >= Duration::from_secs(2));
assert_eq!(result.stdout.trim(), "done");
assert!(registry.outstanding().is_empty());
assert!(matches!(
receiver.try_recv(),
Err(tokio::sync::mpsc::error::TryRecvError::Empty)
));
assert!(!workdir.path().join("logs").exists());
}
#[test]
fn a_fast_command_finishes_in_the_foreground() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let (outcome, registry, mut receiver) = detached_run(
workdir.path(),
runtime.path(),
"echo hi",
Duration::from_secs(10),
);
let result = match outcome {
ShellOutcome::Finished(result) => result,
ShellOutcome::Detached(info) => {
panic!("`echo hi` must not be demoted: {}", info.work_id)
}
};
assert_eq!(result.stdout.trim(), "hi");
assert_eq!(result.exit_code, 0);
assert!(!result.truncated);
assert!(result.full_output_path.is_none());
assert!(registry.outstanding().is_empty());
assert!(
matches!(
receiver.try_recv(),
Err(tokio::sync::mpsc::error::TryRecvError::Empty)
),
"a foreground command produces no completion"
);
}
#[test]
fn a_failing_detached_command_completes_with_its_exit_code() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let (outcome, _registry, mut receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 3; echo to-stderr >&2; exit 7",
Duration::from_secs(1),
);
assert!(matches!(outcome, ShellOutcome::Detached(_)));
let completion = await_completion(&mut receiver);
assert_eq!(completion.exit_code, 7);
assert_eq!(completion.status(), "error");
assert!(
completion.message_text().contains("exit_code: 7"),
"the message names the exit code: {}",
completion.message_text()
);
let log = std::fs::read_to_string(&completion.output_path).unwrap();
assert!(log.starts_with("Command: bash -c "), "{log}");
assert!(
log.contains("\n\nto-stderr\n"),
"stderr is in the output section: {log}"
);
assert!(log.ends_with("\n\nExit code: 7\n"), "{log}");
let (outcome, _registry, mut receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 3; exit 0",
Duration::from_secs(1),
);
assert!(matches!(outcome, ShellOutcome::Detached(_)));
assert_eq!(await_completion(&mut receiver).status(), "ok");
}
#[test]
fn the_demotion_result_names_the_tool_and_stays_small() {
for delivered in [true, false] {
let result = demotion_tool_result("wrk_0a1b", delivered);
let data = result.data.as_deref().unwrap();
assert!(data.len() < 400, "{} bytes: {data}", data.len());
assert!(data.contains("wrk_0a1b"), "{data}");
assert!(data.contains("background-command"), "{data}");
assert!(data.contains("is killed"), "{data}");
for retired in [concat!("nothing to ", "poll"), concat!("no way ", "to ask")] {
assert!(!data.contains(retired), "{retired}: {data}");
}
assert_eq!(data.contains("separate task"), delivered, "{data}");
assert_eq!(
result.summary.as_deref(),
Some("Command still running in the background as wrk_0a1b.")
);
assert_eq!(
result.metadata,
vec![("work_id".to_string(), "wrk_0a1b".to_string())]
);
}
assert_eq!(
demotion_tool_result("wrk_1", false).data.as_deref(),
Some(
"The command is still running and was moved to the background as wrk_1. The \
background-command tool reports on it, waits for it or stops it by that id. A \
command still running when the session ends is killed."
)
);
}
fn demoted(outcome: ShellOutcome) -> DetachedDispatchInfo {
match outcome {
ShellOutcome::Detached(info) => info,
ShellOutcome::Finished(result) => {
panic!("the command finished inside its grace period: {result:?}")
}
}
}
fn read_text(
registry: &DetachedRegistry,
work_id: &str,
waited: Option<Duration>,
) -> (CommandSnapshot, ToolResult) {
let snapshot = registry.read(work_id).expect("the work id was issued");
let (result, _) = crate::background_command::render(&snapshot, waited);
(snapshot, result)
}
fn log_of(snapshot: &CommandSnapshot) -> String {
std::fs::read_to_string(&snapshot.output_path).expect("the log exists while it runs")
}
#[tokio::test]
async fn status_shows_output_so_far_while_the_command_runs() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let started = Instant::now();
let (outcome, registry, _receiver) = detached_run(
workdir.path(),
runtime.path(),
"echo first; sleep 2; echo second >&2; sleep 30",
Duration::from_secs(1),
);
let _guard = KillRunningOnDrop(Arc::clone(®istry));
let info = demoted(outcome);
tokio::time::sleep(Duration::from_millis(2_500).saturating_sub(started.elapsed())).await;
let (snapshot, result) = read_text(®istry, &info.work_id, None);
let data = result.data.unwrap();
assert_eq!(snapshot.state, CommandState::Running, "{data}");
assert!(data.contains("state: running\n"), "{data}");
assert!(data.contains("output_shown: all\n"), "{data}");
assert!(data.ends_with("\n\nfirst\nsecond\n"), "{data}");
let log = log_of(&snapshot);
assert!(log.contains("first") && log.contains("second"), "{log}");
assert!(!log.contains("Exit code:"), "{log}");
assert!(registry.stop(&info.work_id).await);
let (snapshot, _) = read_text(®istry, &info.work_id, None);
assert_eq!(snapshot.state, CommandState::Stopped);
let log = log_of(&snapshot);
assert!(log.contains("\n\nExit code: "), "{log}");
}
#[tokio::test]
async fn status_shows_the_last_16_kib_and_the_log_holds_everything() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let (outcome, registry, _receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 1.5; head -c 50000 /dev/zero | tr '\\0' a; echo; echo TAILMARK; sleep 30",
Duration::from_secs(1),
);
let _guard = KillRunningOnDrop(Arc::clone(®istry));
let info = demoted(outcome);
let expected_bytes = 50_000 + "\nTAILMARK\n".len() as u64;
let deadline = Instant::now() + Duration::from_secs(15);
let (snapshot, result) = loop {
let (snapshot, result) = read_text(®istry, &info.work_id, None);
if snapshot.output_bytes >= expected_bytes {
break (snapshot, result);
}
assert!(
Instant::now() < deadline,
"only {} bytes",
snapshot.output_bytes
);
tokio::time::sleep(Duration::from_millis(50)).await;
};
assert_eq!(snapshot.output_bytes, expected_bytes);
assert!(result.truncated);
let data = result.data.unwrap();
assert!(data.contains("output_bytes: 50010\n"), "{}", &data[..300]);
assert!(
data.contains("output_shown: last 16384 bytes\n\n"),
"{}",
&data[..300]
);
let shown = data.split_once("\n\n").unwrap().1;
let mut expected = "a".repeat(16_384 - "\nTAILMARK\n".len());
expected.push_str("\nTAILMARK\n");
assert_eq!(shown.len(), 16_384);
assert_eq!(shown, expected);
let log = log_of(&snapshot);
assert!(
log.contains(&format!("\n\n{}\nTAILMARK\n", "a".repeat(50_000))),
"the log holds all 50000 bytes"
);
assert!(registry.stop(&info.work_id).await);
let log = log_of(®istry.read(&info.work_id).unwrap());
assert!(
log.contains("TAILMARK\n\n\nExit code: "),
"{}",
&log[log.len() - 40..]
);
}
#[tokio::test]
async fn wait_returns_when_the_command_exits() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let (outcome, registry, _receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 3; echo done; exit 7",
Duration::from_secs(1),
);
let _guard = KillRunningOnDrop(Arc::clone(®istry));
let info = demoted(outcome);
let waiting = Instant::now();
let end = registry
.wait(
&info.work_id,
crate::background_command::effective_wait(Some(30)),
None,
)
.await;
let waited = waiting.elapsed();
assert_eq!(end, WaitEnd::Finished);
assert!(waited < Duration::from_secs(6), "the wait took {waited:?}");
let (snapshot, result) = read_text(®istry, &info.work_id, Some(waited));
let data = result.data.unwrap();
assert_eq!(snapshot.state, CommandState::Exited);
for line in ["state: exited\n", "exit_code: 7\n", "status: error\n"] {
assert!(data.contains(line), "{line}: {data}");
}
assert!(data.ends_with("\n\ndone\n"), "{data}");
assert!(registry.exit_reported(&info.work_id));
}
#[tokio::test]
async fn wait_returns_at_its_bound_with_the_command_still_running() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let (outcome, registry, _receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 60",
Duration::from_secs(1),
);
let _guard = KillRunningOnDrop(Arc::clone(®istry));
let info = demoted(outcome);
let waiting = Instant::now();
let end = registry
.wait(
&info.work_id,
crate::background_command::effective_wait(Some(1)),
None,
)
.await;
let waited = waiting.elapsed();
assert_eq!(end, WaitEnd::TimedOut);
assert!(
waited >= Duration::from_secs(1) && waited < Duration::from_secs(3),
"the wait took {waited:?}"
);
let (snapshot, result) = read_text(®istry, &info.work_id, Some(waited));
let data = result.data.unwrap();
assert_eq!(snapshot.state, CommandState::Running);
assert!(data.contains("waited_secs: 1\n"), "{data}");
assert!(!data.contains("exit_code"), "{data}");
assert!(!registry.exit_reported(&info.work_id));
}
#[tokio::test]
async fn stop_ends_the_command_and_its_children() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let _leader = KillPidFileOnDrop(workdir.path().join("leader.pid"));
let _child = KillPidFileOnDrop(workdir.path().join("child.pid"));
let (outcome, registry, _receiver) = detached_run(
workdir.path(),
runtime.path(),
"echo $$ > leader.pid; sleep 300 > /dev/null 2>&1 & echo $! > child.pid; sleep 300",
Duration::from_secs(1),
);
let _guard = KillRunningOnDrop(Arc::clone(®istry));
let info = demoted(outcome);
let stopping = Instant::now();
assert!(registry.stop(&info.work_id).await);
let took = stopping.elapsed();
assert!(took < Duration::from_secs(5), "the stop took {took:?}");
let (snapshot, result) = read_text(®istry, &info.work_id, None);
let data = result.data.unwrap();
assert_eq!(snapshot.state, CommandState::Stopped, "{data}");
let exit_code = snapshot.finished.as_ref().unwrap().exit_code;
assert!([143, 137].contains(&exit_code), "{data}");
assert!(data.contains("state: stopped\n"), "{data}");
assert_eq!(snapshot.finished.unwrap().resource_limit, None);
for file in ["leader.pid", "child.pid"] {
let pid = read_pid(&workdir.path().join(file));
assert!(
process_dead_within(pid, Duration::from_secs(2)),
"{file}'s process {pid} is still running"
);
}
}
#[tokio::test]
async fn stop_escalates_to_sigkill_when_sigterm_is_ignored() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let _leader = KillPidFileOnDrop(workdir.path().join("leader.pid"));
let (outcome, registry, _receiver) = detached_run(
workdir.path(),
runtime.path(),
"echo $$ > leader.pid; trap '' TERM; while :; do sleep 1; done",
Duration::from_secs(1),
);
let _guard = KillRunningOnDrop(Arc::clone(®istry));
let info = demoted(outcome);
let stopping = Instant::now();
assert!(registry.stop(&info.work_id).await);
let took = stopping.elapsed();
assert!(took < Duration::from_secs(5), "the stop took {took:?}");
assert!(
took >= crate::background_command::STOP_TERM_GRACE,
"{took:?}"
);
let (snapshot, result) = read_text(®istry, &info.work_id, None);
assert_eq!(snapshot.state, CommandState::Stopped, "{:?}", result.data);
assert_eq!(snapshot.finished.unwrap().exit_code, 137);
assert_eq!(registry.signals_sent(&info.work_id), 2);
let pid = read_pid(&workdir.path().join("leader.pid"));
assert!(
process_dead_within(pid, Duration::from_secs(2)),
"{pid} still runs"
);
}
#[tokio::test]
async fn stop_on_a_finished_command_reports_it_unchanged() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let (outcome, registry, mut receiver) = detached_run(
workdir.path(),
runtime.path(),
"sleep 1.5; exit 0",
Duration::from_secs(1),
);
let info = demoted(outcome);
await_completion(&mut receiver);
assert!(registry.stop(&info.work_id).await);
let (snapshot, result) = read_text(®istry, &info.work_id, None);
let data = result.data.unwrap();
assert_eq!(snapshot.state, CommandState::Exited, "{data}");
assert!(data.contains("exit_code: 0\nstatus: ok\n"), "{data}");
assert_eq!(registry.signals_sent(&info.work_id), 0);
assert!(
!registry.stop(&new_work_id()).await,
"an unknown id is not stopped"
);
}
#[test]
fn kill_running_leaves_nothing_without_a_cgroup_scope() {
let workdir = tempfile::tempdir().unwrap();
let runtime = tempfile::tempdir().unwrap();
let _leader = KillPidFileOnDrop(workdir.path().join("leader.pid"));
let _child = KillPidFileOnDrop(workdir.path().join("child.pid"));
let enforcement = ShellEnforcement::environment_only()
.with_runtime_dir(crate::sandbox::test_runtime_dir(runtime.path()), None);
assert!(enforcement.cgroup_scope.is_none());
let (outcome, registry, _receiver) = detached_run_with(
workdir.path(),
&enforcement,
"echo $$ > leader.pid; sleep 300 > /dev/null 2>&1 & echo $! > child.pid; sleep 300",
Duration::from_secs(1),
);
let info = demoted(outcome);
assert_eq!(registry.outstanding().len(), 1);
registry.kill_running();
for file in ["leader.pid", "child.pid"] {
let pid = read_pid(&workdir.path().join(file));
assert!(
process_dead_within(pid, Duration::from_secs(2)),
"{file}'s process {pid} outlived kill_running"
);
}
assert_eq!(registry.signals_sent(&info.work_id), 1);
}
#[test]
fn the_demotion_result_is_a_constant_size() {
for delivered in [true, false] {
the_demotion_result_is_a_constant_size_when(delivered);
}
}
fn the_demotion_result_is_a_constant_size_when(delivered: bool) {
let reduce = |work_id: &str| {
let result = demotion_tool_result(work_id, delivered);
result
.data
.or(result.summary)
.unwrap_or_else(|| "tool returned no data".to_string())
};
let first = reduce(&new_work_id());
let second = reduce(&new_work_id());
assert_eq!(
first.len(),
second.len(),
"two work ids of equal length must produce texts of equal size"
);
for text in [&first, &second] {
let tokens = crate::agent::count_tokens(text);
assert!(
tokens < 120,
"the demotion result costs {tokens} tokens, over the 120-token ceiling"
);
}
assert!(
!first.contains("logs/"),
"the demotion result names no path: {first}"
);
}
fn still_running(work_id: &str, running_ms: u64) -> AbandonedWork {
AbandonedWork {
work_id: work_id.to_string(),
binary: "/usr/bin/bash".to_string(),
command: "sleep 45; echo done".to_string(),
disposition: AbandonedDisposition::StillRunning { running_ms },
}
}
fn report_records() -> (tempfile::TempDir, crate::workdir_fs::WorkdirRoot) {
let dir = tempfile::tempdir().unwrap();
let root = crate::workdir_fs::WorkdirRoot::open(dir.path()).unwrap();
(dir, root)
}
fn finished_too_late(
records_root: &crate::workdir_fs::WorkdirRoot,
work_id: &str,
) -> AbandonedWork {
AbandonedWork {
work_id: work_id.to_string(),
binary: "/usr/bin/bash".to_string(),
command: "sleep 2; echo done".to_string(),
disposition: AbandonedDisposition::FinishedTooLate {
exit_code: 0,
duration_ms: 2_014,
output_path: output_path_for(records_root, work_id).path,
output_bytes: 91,
resource_limit: None,
wait_error: None,
status: "ok",
},
}
}
#[test]
fn a_still_running_command_is_reported_as_killed_with_what_is_known() {
let (records, records_root) = report_records();
let text = abandonment_report_text(
"ses_abc",
&records_root,
&[still_running("wrk_0a1b", 45_012)],
);
assert!(
text.contains("1 background shell command discarded"),
"{text}"
);
assert!(text.contains("Session ses_abc"), "{text}");
assert!(text.contains("work_id: wrk_0a1b"), "{text}");
assert!(text.contains("binary: /usr/bin/bash"), "{text}");
assert!(text.contains("command: sleep 45; echo done"), "{text}");
assert!(
text.contains("state: killed at session end after 45012 ms"),
"{text}"
);
let path = records.path().join("logs/wrk_0a1b.log");
assert!(
text.contains(&format!("before the kill is in {}.", path.display())),
"the report names the log by its absolute path: {text}"
);
assert!(!text.contains("exit_code:"), "no exit code exists: {text}");
for retired in [
"nothing was killed",
"Nothing was waited for",
"keeps running",
] {
assert!(
!text.contains(retired),
"the session's end kills what it started, so the report must not say {retired:?}: \
{text}"
);
}
}
#[test]
fn a_command_that_finished_during_teardown_is_reported_with_its_result() {
let (records, records_root) = report_records();
let text = abandonment_report_text(
"ses_abc",
&records_root,
&[finished_too_late(&records_root, "wrk_0c2d")],
);
assert!(
text.contains("state: finished during teardown after 2014 ms"),
"{text}"
);
assert!(text.contains("status: ok"), "{text}");
assert!(text.contains("exit_code: 0"), "{text}");
let path = records.path().join("logs/wrk_0c2d.log");
assert!(
text.contains(&format!("output: {} (91 bytes)\n", path.display())),
"{text}"
);
assert!(!text.contains("in the capsule workdir"), "{text}");
assert!(!text.contains("killed at session end"), "{text}");
}
#[test]
fn the_report_states_the_condition_once_and_enumerates_every_command() {
let (_records, records_root) = report_records();
let text = abandonment_report_text(
"ses_abc",
&records_root,
&[
still_running("wrk_0a1b", 12),
finished_too_late(&records_root, "wrk_0c2d"),
],
);
assert_eq!(
text.matches("2 background shell commands discarded")
.count(),
1
);
assert_eq!(text.matches("work_id: ").count(), 2);
assert!(text.contains("wrk_0a1b"), "{text}");
assert!(text.contains("wrk_0c2d"), "{text}");
}
#[test]
fn an_attributed_resource_limit_is_named_in_the_report() {
let (_records, records_root) = report_records();
let mut work = finished_too_late(&records_root, "wrk_0c2d");
if let AbandonedDisposition::FinishedTooLate {
resource_limit,
exit_code,
status,
..
} = &mut work.disposition
{
*resource_limit = Some("memory".to_string());
*exit_code = 137;
*status = "error";
}
let text = abandonment_report_text("ses_abc", &records_root, &[work]);
assert!(text.contains("resource_limit: memory"), "{text}");
assert!(text.contains("status: error"), "{text}");
assert!(text.contains("exit_code: 137"), "{text}");
}
#[test]
fn only_a_command_that_finished_carries_a_recovered_result() {
assert_eq!(still_running("wrk_0a1b", 45_012).running_ms(), 45_012);
assert!(still_running("wrk_0a1b", 45_012).recovered().is_none());
let (records, records_root) = report_records();
let finished = finished_too_late(&records_root, "wrk_0c2d");
let path = records.path().join("logs/wrk_0c2d.log");
assert_eq!(finished.running_ms(), 2_014);
assert_eq!(
finished.recovered(),
Some((0, path.to_str().unwrap(), 91)),
"the exit code, the output path and its byte count travel together"
);
}
#[test]
fn a_failed_wait_is_named_beside_the_status_it_explains() {
let (_records, records_root) = report_records();
let mut work = finished_too_late(&records_root, "wrk_0c2d");
if let AbandonedDisposition::FinishedTooLate {
wait_error, status, ..
} = &mut work.disposition
{
*wait_error = Some("no child processes".to_string());
*status = "error";
}
let text = abandonment_report_text("ses_abc", &records_root, &[work]);
assert!(text.contains("status: error"), "{text}");
assert!(text.contains("wait_error: no child processes"), "{text}");
}
#[test]
fn the_report_does_not_claim_nothing_is_recoverable() {
let (_records, records_root) = report_records();
let text =
abandonment_report_text("ses_abc", &records_root, &[still_running("wrk_0a1b", 12)]);
assert!(
!text.contains("No exit code was recorded"),
"the clean-exit report is not the crash report: {text}"
);
}
}