1use std::{
19 collections::{BTreeMap, VecDeque},
20 io::Write as _,
21 sync::{
22 atomic::{AtomicBool, Ordering},
23 Arc, Mutex,
24 },
25 time::{Duration, Instant},
26};
27
28use tokio::sync::{
29 mpsc::{unbounded_channel, UnboundedReceiver, UnboundedSender},
30 watch,
31};
32
33use crate::{
34 bindings::host::murmur::tool::run::{Status, ToolResult},
35 cancel::CancelSignal,
36 origin::{TaskOrigin, TaskProvenance},
37};
38
39pub const WORK_ID_PREFIX: &str = "wrk_";
42
43pub fn new_work_id() -> String {
48 format!("{WORK_ID_PREFIX}{}", uuid::Uuid::now_v7().simple())
49}
50
51#[derive(Debug, Clone, PartialEq, Eq)]
53pub(crate) struct OutputLog {
54 pub relative: String,
57 pub path: String,
60}
61
62pub(crate) fn output_path_for(
70 records_root: &crate::workdir_fs::WorkdirRoot,
71 stem: &str,
72) -> OutputLog {
73 let relative = format!("logs/{stem}.log");
74 let path = records_root
75 .host_path(&relative)
76 .to_string_lossy()
77 .into_owned();
78 OutputLog { relative, path }
79}
80
81#[derive(Debug, Clone)]
83pub(crate) struct DetachedWork {
84 pub work_id: String,
85 pub binary: String,
87 pub command: String,
89 pub started_at_ms: u64,
92}
93
94#[derive(Debug, Clone)]
99pub(crate) struct DetachedCompletion {
100 pub work_id: String,
101 pub binary: String,
102 pub command: String,
103 pub exit_code: i32,
104 pub duration_ms: u64,
105 pub exited_at_ms: u64,
108 pub output_path: String,
111 pub output_bytes: u64,
113 pub resource_limit: Option<String>,
114 pub output_holders: crate::shell::OutputHolders,
117 pub context_id: String,
120 pub provenance: TaskProvenance,
122 pub error: Option<String>,
124}
125
126impl DetachedCompletion {
127 pub(crate) fn message_text(&self) -> String {
135 let mut text = format!(
136 "Background shell command finished.\n\
137 work_id: {}\n\
138 status: {}\n\
139 exit_code: {}\n\
140 duration_ms: {}\n\
141 output: {} ({} bytes)",
142 self.work_id,
143 self.status(),
144 self.exit_code,
145 self.duration_ms,
146 self.output_path,
147 self.output_bytes,
148 );
149 if let Some(limit) = &self.resource_limit {
150 text.push('\n');
151 text.push_str(&crate::resources::resource_limit_line(limit));
152 }
153 if let Some(note) = self.output_holders.note() {
154 text.push('\n');
155 text.push_str(¬e);
156 }
157 if let Some(error) = &self.error {
158 text.push_str(&format!("\nwait_error: {error}"));
159 }
160 text.push_str(
161 "\n\nThe full stdout and stderr are in that file and are not reproduced here.",
162 );
163 text
164 }
165
166 pub(crate) fn status(&self) -> &'static str {
172 if self.exit_code == 0 && self.error.is_none() && self.resource_limit.is_none() {
173 "ok"
174 } else {
175 "error"
176 }
177 }
178}
179
180#[derive(Debug, Clone)]
182pub(crate) struct DetachedDispatchInfo {
183 pub work_id: String,
184 pub binary: String,
185 pub command: String,
186 pub grace_ms: Option<u64>,
190}
191
192pub(crate) fn demotion_tool_result(
201 work_id: &str,
202 delivered: bool,
203 tool_offered: bool,
204) -> ToolResult {
205 let tool = crate::background_command::BACKGROUND_COMMAND_TOOL;
206 let mut data = if tool_offered {
207 format!(
208 "The command is still running and was moved to the background as {work_id}. The \
209 {tool} tool reports on it, waits for it or stops it by that id. A command still \
210 running when the session ends is killed."
211 )
212 } else {
213 format!(
214 "The command is still running and was moved to the background as {work_id}. A \
215 command still running when the session ends is killed."
216 )
217 };
218 match (delivered, tool_offered) {
219 (true, true) => data.push_str(&format!(
220 " If it exits before {tool} has reported its exit, its result also arrives later as a \
221 separate task."
222 )),
223 (true, false) => {
224 data.push_str(" When it exits, its result arrives later as a separate task.");
225 }
226 (false, _) => {}
227 }
228 ToolResult {
229 status: Status::Passed,
230 summary: Some(format!(
231 "Command still running in the background as {work_id}."
232 )),
233 data: Some(data),
234 data_path: None,
235 truncated: false,
236 metadata: vec![("work_id".to_string(), work_id.to_string())],
237 attachments: Vec::new(),
238 }
239}
240
241#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)]
245pub(crate) enum Phase {
246 Running,
248 LeaderExited,
251 Finished,
253}
254
255#[derive(Debug, Clone, Copy, PartialEq, Eq)]
257pub(crate) enum CommandState {
258 Running,
259 Exited,
261 Stopped,
263}
264
265impl CommandState {
266 pub(crate) fn as_str(self) -> &'static str {
267 match self {
268 Self::Running => "running",
269 Self::Exited => "exited",
270 Self::Stopped => "stopped",
271 }
272 }
273}
274
275#[derive(Debug, Clone, Copy, PartialEq, Eq)]
278pub(crate) enum Delivery {
279 BackgroundCommand,
281 Task,
283}
284
285impl Delivery {
286 pub(crate) fn as_str(self) -> &'static str {
288 match self {
289 Self::BackgroundCommand => "background_command",
290 Self::Task => "task",
291 }
292 }
293}
294
295pub(crate) struct LiveOutput {
305 file: Option<std::fs::File>,
307 tail: VecDeque<u8>,
308 section_bytes: u64,
310 write_error: Option<String>,
312}
313
314impl LiveOutput {
315 pub(crate) fn open(
320 records_root: &crate::workdir_fs::WorkdirRoot,
321 relative: &str,
322 command_line: &str,
323 ) -> Self {
324 let mut live = Self {
325 file: None,
326 tail: VecDeque::new(),
327 section_bytes: 0,
328 write_error: None,
329 };
330 match records_root.open_append(relative, crate::workdir_fs::DEFAULT_FILE_MODE) {
331 Ok(file) => {
332 live.file = Some(file);
333 live.write(format!("Command: {command_line}\n\n").as_bytes());
334 }
335 Err(error) => live.write_error = Some(format!("failed to write shell log: {error}")),
336 }
337 live
338 }
339
340 fn write(&mut self, bytes: &[u8]) {
341 let Some(file) = self.file.as_mut() else {
342 return;
343 };
344 if let Err(error) = file.write_all(bytes) {
345 self.file = None;
346 self.write_error
347 .get_or_insert_with(|| format!("failed to write shell log: {error}"));
348 }
349 }
350
351 pub(crate) fn append(&mut self, bytes: &[u8]) {
353 self.write(bytes);
354 self.section_bytes = self.section_bytes.saturating_add(bytes.len() as u64);
355 let keep = crate::shell::MAX_SHELL_OUTPUT_BYTES;
356 if bytes.len() >= keep {
357 self.tail.clear();
358 self.tail.extend(&bytes[bytes.len() - keep..]);
359 } else {
360 let excess = (self.tail.len() + bytes.len()).saturating_sub(keep);
361 self.tail.drain(..excess);
362 self.tail.extend(bytes);
363 }
364 }
365
366 pub(crate) fn finish(&mut self, exit_code: i32) -> Option<String> {
369 self.write(format!("\n\nExit code: {exit_code}\n").as_bytes());
370 self.file = None;
371 self.write_error.clone()
372 }
373}
374
375struct DetachedEntry {
377 work: DetachedWork,
378 started: Instant,
379 pgid: i32,
381 output_path: String,
383 output: Arc<Mutex<LiveOutput>>,
384 leader_running: bool,
388 stop_requested: bool,
390 signals_sent: u32,
392 finished: Option<DetachedCompletion>,
393 delivery: Option<Delivery>,
396 phase: watch::Sender<Phase>,
397}
398
399#[derive(Debug, Clone)]
401pub(crate) struct CommandSnapshot {
402 pub work_id: String,
403 pub state: CommandState,
404 pub elapsed_ms: u64,
406 pub finished: Option<DetachedCompletion>,
408 pub output_path: String,
409 pub output_bytes: u64,
411 pub tail: Vec<u8>,
414 pub delivered_now: bool,
417}
418
419#[derive(Debug, Clone, Copy, PartialEq, Eq)]
421pub(crate) enum WaitEnd {
422 Finished,
423 TimedOut,
424 Canceled,
425 Unknown,
427}
428
429pub(crate) struct DetachedRegistry {
435 entries: Mutex<BTreeMap<String, DetachedEntry>>,
436 reports: UnboundedSender<DetachedReport>,
440}
441
442impl DetachedRegistry {
443 pub(crate) fn new() -> (Arc<Self>, UnboundedReceiver<DetachedReport>) {
444 let (reports, receiver) = unbounded_channel();
445 (
446 Arc::new(Self {
447 entries: Mutex::new(BTreeMap::new()),
448 reports,
449 }),
450 receiver,
451 )
452 }
453
454 fn lock(&self) -> std::sync::MutexGuard<'_, BTreeMap<String, DetachedEntry>> {
455 self.entries.lock().expect("detached registry mutex")
456 }
457
458 pub(crate) fn report(&self, report: DetachedReport) {
460 let _ = self.reports.send(report);
461 }
462
463 pub(crate) fn register(
468 &self,
469 work: DetachedWork,
470 started: Instant,
471 pgid: i32,
472 output_path: String,
473 output: Arc<Mutex<LiveOutput>>,
474 ) {
475 let (phase, _) = watch::channel(Phase::Running);
476 self.lock().insert(
477 work.work_id.clone(),
478 DetachedEntry {
479 work,
480 started,
481 pgid,
482 output_path,
483 output,
484 leader_running: true,
485 stop_requested: false,
486 signals_sent: 0,
487 finished: None,
488 delivery: None,
489 phase,
490 },
491 );
492 }
493
494 pub(crate) fn leader_exited(&self, work_id: &str) {
498 if let Some(entry) = self.lock().get_mut(work_id) {
499 entry.leader_running = false;
500 entry.phase.send_replace(Phase::LeaderExited);
501 }
502 }
503
504 pub(crate) fn complete(&self, mut completion: DetachedCompletion) {
512 {
513 let mut entries = self.lock();
514 if let Some(entry) = entries.get_mut(&completion.work_id) {
515 if entry.stop_requested {
516 completion.resource_limit = None;
517 }
518 entry.leader_running = false;
519 entry.finished = Some(completion.clone());
520 entry.phase.send_replace(Phase::Finished);
521 }
522 }
523 self.report(DetachedReport::Completed(completion));
524 }
525
526 pub(crate) fn outstanding(&self) -> Vec<DetachedWork> {
528 self.lock()
529 .values()
530 .filter(|entry| entry.finished.is_none())
531 .map(|entry| entry.work.clone())
532 .collect()
533 }
534
535 pub(crate) fn read(&self, work_id: &str) -> Option<CommandSnapshot> {
542 let mut entries = self.lock();
543 let entry = entries.get_mut(work_id)?;
544 let delivered_now = entry.finished.is_some() && entry.delivery.is_none();
545 if delivered_now {
546 entry.delivery = Some(Delivery::BackgroundCommand);
547 }
548 let state = match (&entry.finished, entry.stop_requested) {
549 (None, _) => CommandState::Running,
550 (Some(_), false) => CommandState::Exited,
551 (Some(_), true) => CommandState::Stopped,
552 };
553 let elapsed_ms = match &entry.finished {
554 Some(completion) => completion.duration_ms,
555 None => millis(entry.started.elapsed()),
556 };
557 let (output_bytes, tail) = {
558 let output = entry
559 .output
560 .lock()
561 .unwrap_or_else(std::sync::PoisonError::into_inner);
562 (output.section_bytes, output.tail.iter().copied().collect())
563 };
564 Some(CommandSnapshot {
565 work_id: entry.work.work_id.clone(),
566 state,
567 elapsed_ms,
568 finished: entry.finished.clone(),
569 output_path: entry.output_path.clone(),
570 output_bytes,
571 tail,
572 delivered_now,
573 })
574 }
575
576 pub(crate) fn claim_for_task(&self, work_id: &str) -> bool {
580 let mut entries = self.lock();
581 let Some(entry) = entries.get_mut(work_id) else {
582 return true;
583 };
584 if entry.delivery.is_some() {
585 return false;
586 }
587 entry.delivery = Some(Delivery::Task);
588 true
589 }
590
591 pub(crate) fn exit_reported(&self, work_id: &str) -> bool {
594 self.lock()
595 .get(work_id)
596 .is_some_and(|entry| entry.delivery == Some(Delivery::BackgroundCommand))
597 }
598
599 fn phase(&self, work_id: &str) -> Option<watch::Receiver<Phase>> {
600 self.lock()
601 .get(work_id)
602 .map(|entry| entry.phase.subscribe())
603 }
604
605 fn signal_stop(&self, work_id: &str, signal: libc::c_int) -> bool {
608 let mut entries = self.lock();
609 let Some(entry) = entries
610 .get_mut(work_id)
611 .filter(|entry| entry.leader_running)
612 else {
613 return false;
614 };
615 let sent = crate::formation_launch::signal_group(i64::from(entry.pgid), signal);
616 if sent {
617 entry.signals_sent += 1;
618 entry.stop_requested = true;
619 }
620 sent
621 }
622
623 pub(crate) fn kill_running(&self) {
627 for entry in self.lock().values_mut() {
628 if entry.leader_running
629 && crate::formation_launch::signal_group(i64::from(entry.pgid), libc::SIGKILL)
630 {
631 entry.signals_sent += 1;
632 }
633 }
634 }
635
636 pub(crate) async fn wait(
640 &self,
641 work_id: &str,
642 bound: Duration,
643 cancel: Option<&crate::cancel::CancelSignal>,
644 ) -> WaitEnd {
645 let Some(mut phase) = self.phase(work_id) else {
646 return WaitEnd::Unknown;
647 };
648 let canceled = async {
649 match cancel {
650 Some(signal) => signal.canceled().await,
651 None => std::future::pending().await,
652 }
653 };
654 tokio::select! {
655 finished = phase.wait_for(|phase| *phase == Phase::Finished) => {
656 if finished.is_ok() { WaitEnd::Finished } else { WaitEnd::TimedOut }
659 }
660 () = tokio::time::sleep(bound) => WaitEnd::TimedOut,
661 () = canceled => WaitEnd::Canceled,
662 }
663 }
664
665 pub(crate) async fn stop(&self, work_id: &str) -> bool {
673 let Some(mut phase) = self.phase(work_id) else {
674 return false;
675 };
676 if self.signal_stop(work_id, libc::SIGTERM) {
677 let exited = tokio::time::timeout(
678 crate::background_command::STOP_TERM_GRACE,
679 phase.wait_for(|phase| *phase >= Phase::LeaderExited),
680 )
681 .await;
682 if !matches!(exited, Ok(Ok(_))) {
683 self.signal_stop(work_id, libc::SIGKILL);
684 }
685 }
686 let _ = tokio::time::timeout(
687 crate::background_command::STOP_KILL_WAIT,
688 phase.wait_for(|phase| *phase == Phase::Finished),
689 )
690 .await;
691 true
692 }
693
694 #[cfg(test)]
696 pub(crate) fn signals_sent(&self, work_id: &str) -> u32 {
697 self.lock()
698 .get(work_id)
699 .map_or(0, |entry| entry.signals_sent)
700 }
701}
702
703fn millis(duration: Duration) -> u64 {
704 duration.as_millis().try_into().unwrap_or(u64::MAX)
705}
706
707#[cfg(test)]
710pub(crate) struct KillRunningOnDrop(pub(crate) Arc<DetachedRegistry>);
711
712#[cfg(test)]
713impl Drop for KillRunningOnDrop {
714 fn drop(&mut self) {
715 self.0.kill_running();
716 }
717}
718
719pub(crate) struct DetachPolicy {
725 pub grace: Option<Duration>,
729 pub delivered: bool,
732 pub registry: Arc<DetachedRegistry>,
733 pub command: String,
737 pub context_id: String,
738 pub provenance: Option<TaskProvenance>,
742 pub abandoned: Option<AbandonSignal>,
746 pub canceled: Option<CancelSignal>,
751}
752
753#[derive(Debug, Clone, Default)]
758pub(crate) struct AbandonSignal(Arc<AtomicBool>);
759
760impl AbandonSignal {
761 pub(crate) fn new() -> Self {
762 Self::default()
763 }
764
765 pub(crate) fn raise(&self) {
766 self.0.store(true, Ordering::SeqCst);
767 }
768
769 pub(crate) fn is_raised(&self) -> bool {
770 self.0.load(Ordering::SeqCst)
771 }
772}
773
774impl DetachPolicy {
775 pub(crate) fn completion_provenance(&self) -> TaskProvenance {
777 TaskProvenance::derive(
778 TaskOrigin::Completion,
779 self.provenance.map(|task| task.trust()),
780 )
781 }
782}
783
784#[derive(Debug, Clone)]
793pub(crate) enum AbandonedDisposition {
794 StillRunning {
798 running_ms: u64,
800 },
801 FinishedTooLate {
805 exit_code: i32,
806 duration_ms: u64,
808 output_path: String,
810 output_bytes: u64,
811 resource_limit: Option<String>,
812 wait_error: Option<String>,
815 status: &'static str,
817 },
818}
819
820#[derive(Debug, Clone)]
822pub(crate) struct AbandonedWork {
823 pub work_id: String,
824 pub binary: String,
826 pub command: String,
829 pub disposition: AbandonedDisposition,
830}
831
832impl AbandonedWork {
833 pub(crate) fn running_ms(&self) -> u64 {
836 match &self.disposition {
837 AbandonedDisposition::StillRunning { running_ms } => *running_ms,
838 AbandonedDisposition::FinishedTooLate { duration_ms, .. } => *duration_ms,
839 }
840 }
841
842 pub(crate) fn recovered(&self) -> Option<(i32, &str, u64)> {
847 match &self.disposition {
848 AbandonedDisposition::StillRunning { .. } => None,
849 AbandonedDisposition::FinishedTooLate {
850 exit_code,
851 output_path,
852 output_bytes,
853 ..
854 } => Some((*exit_code, output_path.as_str(), *output_bytes)),
855 }
856 }
857}
858
859pub(crate) fn abandonment_report_text(
870 session_id: &str,
871 records_root: &crate::workdir_fs::WorkdirRoot,
872 abandoned: &[AbandonedWork],
873) -> String {
874 let count = abandoned.len();
875 let plural = if count == 1 { "command" } else { "commands" };
876 let mut text = format!(
877 "[capsule-runtime] {count} background shell {plural} discarded at session end.\n\n\
878 Session {session_id} ended while {count} demoted shell {plural} {} unaccounted for. \
879 Every process the session started was killed when it ended; what is known about each \
880 command is below.\n",
881 if count == 1 { "was" } else { "were" }
882 );
883 for work in abandoned {
884 text.push_str(&format!(
885 "\nwork_id: {}\nbinary: {}\ncommand: {}\n",
886 work.work_id, work.binary, work.command
887 ));
888 match &work.disposition {
889 AbandonedDisposition::StillRunning { running_ms } => {
890 text.push_str(&format!(
891 "state: killed at session end after {running_ms} ms\n\
892 result: none — it was killed before it finished, so no task carries an exit \
893 code. What it printed before the kill is in {}.\n",
894 output_path_for(records_root, &work.work_id).path
895 ));
896 }
897 AbandonedDisposition::FinishedTooLate {
898 exit_code,
899 duration_ms,
900 output_path,
901 output_bytes,
902 resource_limit,
903 wait_error,
904 status,
905 } => {
906 text.push_str(&format!(
907 "state: finished during teardown after {duration_ms} ms\n\
908 status: {status}\n\
909 exit_code: {exit_code}\n"
910 ));
911 if let Some(limit) = resource_limit {
912 text.push_str(&format!("resource_limit: {limit}\n"));
913 }
914 if let Some(error) = wait_error {
915 text.push_str(&format!("wait_error: {error}\n"));
916 }
917 text.push_str(&format!(
918 "output: {output_path} ({output_bytes} bytes)\n\
919 result: on disk — it finished too late for any task to carry it back to the \
920 agent.\n"
921 ));
922 }
923 }
924 }
925 text.push_str(
926 "\nA session's end kills every command it demoted and every process its shell calls \
927 started in the background. Declare lifecycle.task_acceptance: queue with \
928 lifecycle.after_task: sleep for a session that outlives its task and can be told the \
929 result instead.",
930 );
931 text
932}
933
934#[derive(Debug, Clone)]
943pub(crate) struct LostWork {
944 pub work_id: String,
945 pub binary: String,
947 pub command: String,
949 pub detached_at_ms: u64,
951}
952
953#[derive(Debug, Clone)]
959pub(crate) struct LostReport {
960 pub started_in_session: String,
963 pub lost: Vec<LostWork>,
965 pub context_id: String,
967 pub provenance: TaskProvenance,
970 pub task_id: String,
973}
974
975impl LostReport {
976 pub(crate) fn message_text(&self) -> String {
985 let mut text = format!(
986 "Background shell commands from an earlier session were never accounted for.\n\
987 \n\
988 Session {} ended without recording what became of the commands below; they were \
989 running in the background at the time. No exit code was recorded for any of them, \
990 and whether each command finished at all is unknown.\n",
991 self.started_in_session
992 );
993 for work in &self.lost {
994 text.push_str(&format!(
995 "\nwork_id: {}\ndetached_at_ms: {}\n",
996 work.work_id, work.detached_at_ms
997 ));
998 }
999 text.push_str(
1000 "\nNone of these is known to have succeeded and none is known to have failed. Treat \
1001 each as unknown, and start the work again only if it still matters.",
1002 );
1003 text
1004 }
1005}
1006
1007#[derive(Debug, Clone)]
1012pub(crate) enum DetachedReport {
1013 Completed(DetachedCompletion),
1014 Lost(LostReport),
1015}
1016
1017#[cfg(test)]
1018mod tests {
1019 use super::*;
1020
1021 use std::{
1022 path::{Path, PathBuf},
1023 time::{Duration, Instant},
1024 };
1025
1026 use crate::{
1027 origin::TrustClass,
1028 sandbox::ShellEnforcement,
1029 shell::{
1030 run_shell,
1031 test_support::{process_dead_within, read_pid, KillPidFileOnDrop},
1032 ShellOutcome,
1033 },
1034 types::CapabilityPolicy,
1035 };
1036
1037 fn bash_policy() -> CapabilityPolicy {
1038 CapabilityPolicy {
1039 shell_allow: vec!["bash".to_string()],
1040 ..Default::default()
1041 }
1042 }
1043
1044 fn records_dir(base: &Path) -> PathBuf {
1046 base.join(crate::records_dir::RECORDS_DIR_NAME)
1047 }
1048
1049 fn detached_run(
1053 workdir: &Path,
1054 runtime_base: &Path,
1055 script: &str,
1056 grace: impl Into<Option<Duration>>,
1057 ) -> (
1058 ShellOutcome,
1059 Arc<DetachedRegistry>,
1060 UnboundedReceiver<DetachedReport>,
1061 ) {
1062 detached_run_with(
1063 workdir,
1064 &ShellEnforcement::environment_only()
1065 .with_runtime_dir(crate::sandbox::test_runtime_dir(runtime_base), None),
1066 script,
1067 grace,
1068 )
1069 }
1070
1071 fn detached_run_with(
1073 workdir: &Path,
1074 enforcement: &ShellEnforcement,
1075 script: &str,
1076 grace: impl Into<Option<Duration>>,
1077 ) -> (
1078 ShellOutcome,
1079 Arc<DetachedRegistry>,
1080 UnboundedReceiver<DetachedReport>,
1081 ) {
1082 let (registry, receiver) = DetachedRegistry::new();
1083 let outcome = run_shell(
1084 "bash",
1085 &["-c", script],
1086 &[],
1087 &crate::workdir_fs::WorkdirRoot::open(workdir).unwrap(),
1088 &bash_policy(),
1089 enforcement,
1090 Some(DetachPolicy {
1091 grace: grace.into(),
1092 delivered: true,
1093 registry: Arc::clone(®istry),
1094 command: script.to_string(),
1095 context_id: "ctx_detached_tests".to_string(),
1096 provenance: Some(TaskProvenance::derive(TaskOrigin::User, None)),
1097 abandoned: None,
1098 canceled: None,
1099 }),
1100 )
1101 .expect("a declared binary runs");
1102 (outcome, registry, receiver)
1103 }
1104
1105 fn await_completion(receiver: &mut UnboundedReceiver<DetachedReport>) -> DetachedCompletion {
1111 let deadline = Instant::now() + Duration::from_secs(30);
1112 loop {
1113 match receiver.try_recv() {
1114 Ok(DetachedReport::Completed(completion)) => return completion,
1115 Ok(other) => panic!("a shell command's completion was expected; got {other:?}"),
1116 Err(tokio::sync::mpsc::error::TryRecvError::Empty) => {
1117 assert!(
1118 Instant::now() < deadline,
1119 "timed out waiting for the detached completion"
1120 );
1121 std::thread::sleep(Duration::from_millis(25));
1122 }
1123 Err(error) => panic!("the completion channel closed early: {error}"),
1124 }
1125 }
1126 }
1127
1128 fn completion_provenance() -> TaskProvenance {
1129 TaskProvenance::derive(TaskOrigin::Completion, Some(TrustClass::Untrusted))
1130 }
1131
1132 #[test]
1135 fn no_two_completions_share_an_opening_line() {
1136 let outcome = crate::delegation::DelegationOutcome {
1137 delegation_id: "dlg_0001".to_string(),
1138 capsule_name: "worker".to_string(),
1139 capsule_version: "0.1.0".to_string(),
1140 session_id: "ses_child".to_string(),
1141 status: crate::delegation::DelegationStatus::Ok,
1142 result_path: None,
1143 workdir: "/tmp/child".to_string(),
1144 duration_ms: 1,
1145 detail: None,
1146 reported_by: crate::delegation::Reporter::Launcher,
1147 delivered: true,
1148 delivery_error: None,
1149 };
1150 let completion = DetachedCompletion {
1151 work_id: "wrk_0001".to_string(),
1152 binary: "bash".to_string(),
1153 command: "sleep 3".to_string(),
1154 exit_code: 0,
1155 duration_ms: 3_000,
1156 exited_at_ms: 1_000,
1157 output_path: "/home/test/.murmur/records/work/ses_1/logs/wrk_0001.log".to_string(),
1158 output_bytes: 0,
1159 resource_limit: None,
1160 output_holders: crate::shell::OutputHolders::Closed,
1161 context_id: "ctx_1".to_string(),
1162 provenance: completion_provenance(),
1163 error: None,
1164 };
1165 let texts = [
1166 ("delegation outcome", outcome.message_text()),
1167 ("detached shell completion", completion.message_text()),
1168 ];
1169 for (index, (name, text)) in texts.iter().enumerate() {
1170 let opening = text.lines().next().unwrap_or_default();
1171 assert!(!opening.is_empty(), "{name} opens with nothing");
1172 for (other_name, other) in texts.iter().skip(index + 1) {
1173 assert_ne!(
1174 opening,
1175 other.lines().next().unwrap_or_default(),
1176 "{name} and {other_name} open with the same line"
1177 );
1178 }
1179 }
1180 }
1181
1182 #[test]
1185 fn a_completion_names_its_limit_in_the_shared_wording() {
1186 let completion = DetachedCompletion {
1187 work_id: "wrk_0001".to_string(),
1188 binary: "bash".to_string(),
1189 command: "make -j64".to_string(),
1190 exit_code: 1,
1191 duration_ms: 3_000,
1192 exited_at_ms: 1_000,
1193 output_path: "/home/test/.murmur/records/work/ses_1/logs/wrk_0001.log".to_string(),
1194 output_bytes: 0,
1195 resource_limit: Some("cgroup_pids_max".into()),
1196 output_holders: crate::shell::OutputHolders::Closed,
1197 context_id: "ctx_1".to_string(),
1198 provenance: completion_provenance(),
1199 error: None,
1200 };
1201 let text = completion.message_text();
1202 let expected = crate::resources::resource_limit_line("cgroup_pids_max");
1203
1204 assert!(
1205 text.lines().any(|line| line == expected),
1206 "no limit line in:\n{text}"
1207 );
1208 assert_eq!(
1209 text.lines().next(),
1210 Some("Background shell command finished.")
1211 );
1212 assert_eq!(completion.status(), "error");
1213 assert!(text.ends_with("are not reproduced here."), "{text}");
1214 }
1215
1216 #[test]
1219 fn a_completion_names_the_work_id_and_not_the_command() {
1220 let completion = DetachedCompletion {
1221 work_id: "wrk_0001".to_string(),
1222 binary: "/usr/bin/bash".to_string(),
1223 command: "make -j64".to_string(),
1224 exit_code: 0,
1225 duration_ms: 3_000,
1226 exited_at_ms: 1_000,
1227 output_path: "/home/test/.murmur/records/work/ses_1/logs/wrk_0001.log".to_string(),
1228 output_bytes: 12,
1229 resource_limit: None,
1230 output_holders: crate::shell::OutputHolders::Closed,
1231 context_id: "ctx_1".to_string(),
1232 provenance: completion_provenance(),
1233 error: Some("the wait failed".to_string()),
1234 };
1235 assert_eq!(
1236 completion.message_text(),
1237 "Background shell command finished.\n\
1238 work_id: wrk_0001\n\
1239 status: error\n\
1240 exit_code: 0\n\
1241 duration_ms: 3000\n\
1242 output: /home/test/.murmur/records/work/ses_1/logs/wrk_0001.log (12 bytes)\n\
1243 wait_error: the wait failed\n\
1244 \n\
1245 The full stdout and stderr are in that file and are not reproduced here."
1246 );
1247 }
1248
1249 #[test]
1252 fn a_lost_report_names_each_work_id_and_not_the_command() {
1253 let lost = |work_id: &str, command: &str, detached_at_ms| LostWork {
1254 work_id: work_id.to_string(),
1255 binary: "/usr/bin/bash".to_string(),
1256 command: command.to_string(),
1257 detached_at_ms,
1258 };
1259 let report = LostReport {
1260 started_in_session: "ses_prior".to_string(),
1261 lost: vec![
1262 lost("wrk_one", "sleep 60", 1750),
1263 lost("wrk_two", "make test", 2500),
1264 ],
1265 context_id: "ctx_1".to_string(),
1266 provenance: completion_provenance(),
1267 task_id: "tsk_1".to_string(),
1268 };
1269 let text = report.message_text();
1270 assert!(
1271 text.contains(
1272 "\nwork_id: wrk_one\ndetached_at_ms: 1750\n\nwork_id: wrk_two\ndetached_at_ms: 2500\n"
1273 ),
1274 "{text}"
1275 );
1276 assert!(text.starts_with(
1277 "Background shell commands from an earlier session were never accounted for.\n\n\
1278 Session ses_prior ended without recording what became of the commands below;"
1279 ));
1280 assert!(
1281 text.ends_with("start the work again only if it still matters."),
1282 "{text}"
1283 );
1284 for absent in [
1285 "binary:",
1286 "command:",
1287 "/usr/bin/bash",
1288 "sleep 60",
1289 "make test",
1290 ] {
1291 assert!(!text.contains(absent), "{absent} in:\n{text}");
1292 }
1293 }
1294
1295 #[test]
1298 fn a_demoted_command_completes_when_its_background_holders_are_killed() {
1299 let workdir = tempfile::tempdir().unwrap();
1300 let runtime = tempfile::tempdir().unwrap();
1301 let _sleeper = KillPidFileOnDrop(workdir.path().join("sleeper.pid"));
1302 let (outcome, _registry, mut receiver) = detached_run(
1303 workdir.path(),
1304 runtime.path(),
1305 "sleep 2; sleep 300 & echo $! > sleeper.pid; echo started",
1306 Duration::from_secs(1),
1307 );
1308 let ShellOutcome::Detached(info) = outcome else {
1309 panic!("a two-second command must not finish inside a one-second grace: {outcome:?}");
1310 };
1311
1312 let waiting = Instant::now();
1313 let completion = await_completion(&mut receiver);
1314 let waited = waiting.elapsed();
1315 assert!(
1316 waited < Duration::from_secs(15),
1317 "the completion took {waited:?}"
1318 );
1319 assert_eq!(completion.work_id, info.work_id);
1320 assert_eq!(completion.exit_code, 0);
1321 assert_eq!(
1322 completion.output_holders,
1323 crate::shell::OutputHolders::Killed
1324 );
1325 let note = crate::shell::OutputHolders::Killed.note().unwrap();
1326 let text = completion.message_text();
1327 assert!(text.lines().any(|line| line == note), "{text}");
1328 assert!(text.ends_with("are not reproduced here."), "{text}");
1329 let log = std::fs::read_to_string(&completion.output_path).unwrap();
1330 assert!(log.contains("started"), "{log}");
1331
1332 let sleeper = read_pid(&workdir.path().join("sleeper.pid"));
1333 assert!(
1334 process_dead_within(sleeper, Duration::from_secs(2)),
1335 "the background sleeper {sleeper} is still running"
1336 );
1337 }
1338
1339 #[test]
1342 fn a_command_outrunning_the_grace_period_is_demoted() {
1343 let workdir = tempfile::tempdir().unwrap();
1344 let runtime = tempfile::tempdir().unwrap();
1345 let started = Instant::now();
1346 let (outcome, registry, mut receiver) = detached_run(
1349 workdir.path(),
1350 runtime.path(),
1351 "sleep 3; printf 'fin%s' 'ished-marker'",
1352 Duration::from_secs(1),
1353 );
1354
1355 let info = match outcome {
1356 ShellOutcome::Detached(info) => info,
1357 ShellOutcome::Finished(result) => {
1358 panic!(
1359 "a three-second command must not finish inside a one-second grace: {result:?}"
1360 )
1361 }
1362 };
1363 assert!(
1364 started.elapsed() < Duration::from_secs(3),
1365 "the call returned only after the command did"
1366 );
1367 assert!(
1368 info.work_id.starts_with(WORK_ID_PREFIX)
1369 && info.work_id[WORK_ID_PREFIX.len()..]
1370 .chars()
1371 .all(|c| c.is_ascii_hexdigit() && !c.is_ascii_uppercase()),
1372 "work id {} must match ^wrk_[0-9a-f]+$",
1373 info.work_id
1374 );
1375 assert_eq!(info.grace_ms, Some(1_000));
1376 assert_eq!(
1377 registry
1378 .outstanding()
1379 .iter()
1380 .map(|work| work.work_id.clone())
1381 .collect::<Vec<_>>(),
1382 vec![info.work_id.clone()],
1383 "the work is registered before the handle is returned"
1384 );
1385
1386 let completion = await_completion(&mut receiver);
1387 assert_eq!(completion.work_id, info.work_id);
1388 assert_eq!(completion.exit_code, 0);
1389 assert_eq!(completion.status(), "ok");
1390 let expected_path = records_dir(runtime.path())
1391 .join("logs")
1392 .join(format!("{}.log", info.work_id));
1393 assert!(expected_path.is_absolute());
1394 assert_eq!(
1395 completion.output_path,
1396 expected_path.to_string_lossy(),
1397 "the completion names <records dir>/logs/<work_id>.log by its absolute path"
1398 );
1399 assert_eq!(completion.provenance.origin(), TaskOrigin::Completion);
1400 assert_eq!(completion.provenance.trust(), TrustClass::Trusted);
1401 assert_eq!(completion.context_id, "ctx_detached_tests");
1402 assert!(
1403 registry.outstanding().is_empty(),
1404 "a completed command is no longer outstanding"
1405 );
1406
1407 let log = std::fs::read_to_string(&completion.output_path)
1408 .expect("the completion's output file exists");
1409 assert!(
1410 log.contains("finished-marker"),
1411 "the output is in the log: {log}"
1412 );
1413 assert_eq!(completion.output_bytes, log.len() as u64);
1414 let text = completion.message_text();
1415 assert!(
1416 !text.contains("finished-marker"),
1417 "the output never reaches the agent: {text}"
1418 );
1419 assert!(
1420 text.contains(&format!(
1421 "output: {} ({} bytes)",
1422 completion.output_path, completion.output_bytes
1423 )),
1424 "{text}"
1425 );
1426 assert!(!text.contains("in the capsule workdir"), "{text}");
1427 assert!(
1428 !workdir.path().join("logs").exists(),
1429 "nothing is written into the accessible workdir"
1430 );
1431 }
1432
1433 #[test]
1436 fn with_no_records_directory_a_slow_command_is_not_demoted() {
1437 let workdir = tempfile::tempdir().unwrap();
1438 let base = tempfile::tempdir().unwrap();
1439 let started = Instant::now();
1440 let (outcome, registry, mut receiver) = detached_run_with(
1441 workdir.path(),
1442 &ShellEnforcement::environment_only().with_runtime_dir(
1443 crate::runtime_dir::RuntimeDirRoots {
1444 records: None,
1445 ..crate::sandbox::test_runtime_dir(base.path())
1446 },
1447 None,
1448 ),
1449 "sleep 2; echo done",
1450 Duration::from_millis(200),
1451 );
1452
1453 let result = match outcome {
1454 ShellOutcome::Finished(result) => result,
1455 ShellOutcome::Detached(info) => {
1456 panic!(
1457 "no records directory, yet the command was demoted as {}",
1458 info.work_id
1459 )
1460 }
1461 };
1462 assert!(started.elapsed() >= Duration::from_secs(2));
1463 assert_eq!(result.stdout.trim(), "done");
1464 assert!(registry.outstanding().is_empty());
1465 assert!(matches!(
1466 receiver.try_recv(),
1467 Err(tokio::sync::mpsc::error::TryRecvError::Empty)
1468 ));
1469 assert!(!workdir.path().join("logs").exists());
1470 }
1471
1472 #[test]
1475 fn with_no_grace_a_slow_command_finishes_in_the_foreground() {
1476 let workdir = tempfile::tempdir().unwrap();
1477 let runtime = tempfile::tempdir().unwrap();
1478 let started = Instant::now();
1479 let (outcome, registry, mut receiver) = detached_run(
1480 workdir.path(),
1481 runtime.path(),
1482 "sleep 3; echo finished",
1483 None,
1484 );
1485
1486 let result = match outcome {
1487 ShellOutcome::Finished(result) => result,
1488 ShellOutcome::Detached(info) => {
1489 panic!("no grace, yet the command was demoted as {}", info.work_id)
1490 }
1491 };
1492 assert!(started.elapsed() >= Duration::from_secs(3));
1493 assert_eq!(result.stdout.trim(), "finished");
1494 assert_eq!(result.exit_code, 0);
1495 assert!(registry.outstanding().is_empty());
1496 assert!(matches!(
1497 receiver.try_recv(),
1498 Err(tokio::sync::mpsc::error::TryRecvError::Empty)
1499 ));
1500 }
1501
1502 #[test]
1504 fn a_zero_grace_demotes_at_the_first_poll() {
1505 let workdir = tempfile::tempdir().unwrap();
1506 let runtime = tempfile::tempdir().unwrap();
1507 let started = Instant::now();
1508 let (outcome, registry, _receiver) = detached_run(
1509 workdir.path(),
1510 runtime.path(),
1511 "sleep 5",
1512 Some(Duration::ZERO),
1513 );
1514
1515 let ShellOutcome::Detached(info) = outcome else {
1516 panic!("a zero grace must demote a five-second command: {outcome:?}");
1517 };
1518 assert!(
1519 started.elapsed() < Duration::from_secs(1),
1520 "demotion took {:?}",
1521 started.elapsed()
1522 );
1523 assert_eq!(info.grace_ms, Some(0));
1524 registry.kill_running();
1525 }
1526
1527 #[test]
1529 fn a_fast_command_finishes_in_the_foreground() {
1530 let workdir = tempfile::tempdir().unwrap();
1531 let runtime = tempfile::tempdir().unwrap();
1532 let (outcome, registry, mut receiver) = detached_run(
1533 workdir.path(),
1534 runtime.path(),
1535 "echo hi",
1536 Duration::from_secs(10),
1537 );
1538
1539 let result = match outcome {
1540 ShellOutcome::Finished(result) => result,
1541 ShellOutcome::Detached(info) => {
1542 panic!("`echo hi` must not be demoted: {}", info.work_id)
1543 }
1544 };
1545 assert_eq!(result.stdout.trim(), "hi");
1546 assert_eq!(result.exit_code, 0);
1547 assert!(!result.truncated);
1548 assert!(result.full_output_path.is_none());
1549 assert!(registry.outstanding().is_empty());
1550 assert!(
1551 matches!(
1552 receiver.try_recv(),
1553 Err(tokio::sync::mpsc::error::TryRecvError::Empty)
1554 ),
1555 "a foreground command produces no completion"
1556 );
1557 }
1558
1559 #[test]
1561 fn a_failing_detached_command_completes_with_its_exit_code() {
1562 let workdir = tempfile::tempdir().unwrap();
1563 let runtime = tempfile::tempdir().unwrap();
1564 let (outcome, _registry, mut receiver) = detached_run(
1565 workdir.path(),
1566 runtime.path(),
1567 "sleep 3; echo to-stderr >&2; exit 7",
1568 Duration::from_secs(1),
1569 );
1570 assert!(matches!(outcome, ShellOutcome::Detached(_)));
1571
1572 let completion = await_completion(&mut receiver);
1573 assert_eq!(completion.exit_code, 7);
1574 assert_eq!(completion.status(), "error");
1575 assert!(
1576 completion.message_text().contains("exit_code: 7"),
1577 "the message names the exit code: {}",
1578 completion.message_text()
1579 );
1580
1581 let log = std::fs::read_to_string(&completion.output_path).unwrap();
1582 assert!(log.starts_with("Command: bash -c "), "{log}");
1583 assert!(
1584 log.contains("\n\nto-stderr\n"),
1585 "stderr is in the output section: {log}"
1586 );
1587 assert!(log.ends_with("\n\nExit code: 7\n"), "{log}");
1588
1589 let (outcome, _registry, mut receiver) = detached_run(
1590 workdir.path(),
1591 runtime.path(),
1592 "sleep 3; exit 0",
1593 Duration::from_secs(1),
1594 );
1595 assert!(matches!(outcome, ShellOutcome::Detached(_)));
1596 assert_eq!(await_completion(&mut receiver).status(), "ok");
1597 }
1598
1599 #[test]
1603 fn the_demotion_result_names_the_tool_and_stays_small() {
1604 for (delivered, tool_offered) in
1605 [(true, true), (false, true), (true, false), (false, false)]
1606 {
1607 let result = demotion_tool_result("wrk_0a1b", delivered, tool_offered);
1608 let data = result.data.as_deref().unwrap();
1609 assert!(data.len() < 400, "{} bytes: {data}", data.len());
1610 assert!(data.contains("wrk_0a1b"), "{data}");
1611 assert_eq!(data.contains("background-command"), tool_offered, "{data}");
1612 assert_eq!(data.contains(" tool"), tool_offered, "{data}");
1613 assert!(data.contains("is killed"), "{data}");
1614 for retired in [concat!("nothing to ", "poll"), concat!("no way ", "to ask")] {
1615 assert!(!data.contains(retired), "{retired}: {data}");
1616 }
1617 assert_eq!(data.contains("separate task"), delivered, "{data}");
1618 assert_eq!(
1619 result.summary.as_deref(),
1620 Some("Command still running in the background as wrk_0a1b.")
1621 );
1622 assert_eq!(
1623 result.metadata,
1624 vec![("work_id".to_string(), "wrk_0a1b".to_string())]
1625 );
1626 }
1627 assert_eq!(
1628 demotion_tool_result("wrk_1", false, true).data.as_deref(),
1629 Some(
1630 "The command is still running and was moved to the background as wrk_1. The \
1631 background-command tool reports on it, waits for it or stops it by that id. A \
1632 command still running when the session ends is killed."
1633 )
1634 );
1635 assert_eq!(
1636 demotion_tool_result("wrk_1", true, true).data.as_deref(),
1637 Some(
1638 "The command is still running and was moved to the background as wrk_1. The \
1639 background-command tool reports on it, waits for it or stops it by that id. A \
1640 command still running when the session ends is killed. If it exits before \
1641 background-command has reported its exit, its result also arrives later as a \
1642 separate task."
1643 )
1644 );
1645 assert_eq!(
1646 demotion_tool_result("wrk_1", false, false).data.as_deref(),
1647 Some(
1648 "The command is still running and was moved to the background as wrk_1. A \
1649 command still running when the session ends is killed."
1650 )
1651 );
1652 assert_eq!(
1653 demotion_tool_result("wrk_1", true, false).data.as_deref(),
1654 Some(
1655 "The command is still running and was moved to the background as wrk_1. A \
1656 command still running when the session ends is killed. When it exits, its \
1657 result arrives later as a separate task."
1658 )
1659 );
1660 }
1661
1662 fn demoted(outcome: ShellOutcome) -> DetachedDispatchInfo {
1665 match outcome {
1666 ShellOutcome::Detached(info) => info,
1667 ShellOutcome::Finished(result) => {
1668 panic!("the command finished inside its grace period: {result:?}")
1669 }
1670 }
1671 }
1672
1673 fn read_text(
1675 registry: &DetachedRegistry,
1676 work_id: &str,
1677 waited: Option<Duration>,
1678 ) -> (CommandSnapshot, ToolResult) {
1679 let snapshot = registry.read(work_id).expect("the work id was issued");
1680 let (result, _) = crate::background_command::render(&snapshot, waited);
1681 (snapshot, result)
1682 }
1683
1684 fn log_of(snapshot: &CommandSnapshot) -> String {
1685 std::fs::read_to_string(&snapshot.output_path).expect("the log exists while it runs")
1686 }
1687
1688 #[tokio::test]
1691 async fn status_shows_output_so_far_while_the_command_runs() {
1692 let workdir = tempfile::tempdir().unwrap();
1693 let runtime = tempfile::tempdir().unwrap();
1694 let started = Instant::now();
1695 let (outcome, registry, _receiver) = detached_run(
1696 workdir.path(),
1697 runtime.path(),
1698 "echo first; sleep 2; echo second >&2; sleep 30",
1699 Duration::from_secs(1),
1700 );
1701 let _guard = KillRunningOnDrop(Arc::clone(®istry));
1702 let info = demoted(outcome);
1703
1704 tokio::time::sleep(Duration::from_millis(2_500).saturating_sub(started.elapsed())).await;
1705 let (snapshot, result) = read_text(®istry, &info.work_id, None);
1706 let data = result.data.unwrap();
1707 assert_eq!(snapshot.state, CommandState::Running, "{data}");
1708 assert!(data.contains("state: running\n"), "{data}");
1709 assert!(data.contains("output_shown: all\n"), "{data}");
1710 assert!(data.ends_with("\n\nfirst\nsecond\n"), "{data}");
1711 let log = log_of(&snapshot);
1712 assert!(log.contains("first") && log.contains("second"), "{log}");
1713 assert!(!log.contains("Exit code:"), "{log}");
1714
1715 assert!(registry.stop(&info.work_id).await);
1716 let (snapshot, _) = read_text(®istry, &info.work_id, None);
1717 assert_eq!(snapshot.state, CommandState::Stopped);
1718 let log = log_of(&snapshot);
1719 assert!(log.contains("\n\nExit code: "), "{log}");
1720 }
1721
1722 #[tokio::test]
1725 async fn status_shows_the_last_16_kib_and_the_log_holds_everything() {
1726 let workdir = tempfile::tempdir().unwrap();
1727 let runtime = tempfile::tempdir().unwrap();
1728 let (outcome, registry, _receiver) = detached_run(
1729 workdir.path(),
1730 runtime.path(),
1731 "sleep 1.5; head -c 50000 /dev/zero | tr '\\0' a; echo; echo TAILMARK; sleep 30",
1732 Duration::from_secs(1),
1733 );
1734 let _guard = KillRunningOnDrop(Arc::clone(®istry));
1735 let info = demoted(outcome);
1736
1737 let expected_bytes = 50_000 + "\nTAILMARK\n".len() as u64;
1738 let deadline = Instant::now() + Duration::from_secs(15);
1739 let (snapshot, result) = loop {
1740 let (snapshot, result) = read_text(®istry, &info.work_id, None);
1741 if snapshot.output_bytes >= expected_bytes {
1742 break (snapshot, result);
1743 }
1744 assert!(
1745 Instant::now() < deadline,
1746 "only {} bytes",
1747 snapshot.output_bytes
1748 );
1749 tokio::time::sleep(Duration::from_millis(50)).await;
1750 };
1751 assert_eq!(snapshot.output_bytes, expected_bytes);
1752 assert!(result.truncated);
1753 let data = result.data.unwrap();
1754 assert!(data.contains("output_bytes: 50010\n"), "{}", &data[..300]);
1755 assert!(
1756 data.contains("output_shown: last 16384 bytes\n\n"),
1757 "{}",
1758 &data[..300]
1759 );
1760 let shown = data.split_once("\n\n").unwrap().1;
1761 let mut expected = "a".repeat(16_384 - "\nTAILMARK\n".len());
1762 expected.push_str("\nTAILMARK\n");
1763 assert_eq!(shown.len(), 16_384);
1764 assert_eq!(shown, expected);
1765 let log = log_of(&snapshot);
1766 assert!(
1767 log.contains(&format!("\n\n{}\nTAILMARK\n", "a".repeat(50_000))),
1768 "the log holds all 50000 bytes"
1769 );
1770
1771 assert!(registry.stop(&info.work_id).await);
1772 let log = log_of(®istry.read(&info.work_id).unwrap());
1773 assert!(
1774 log.contains("TAILMARK\n\n\nExit code: "),
1775 "{}",
1776 &log[log.len() - 40..]
1777 );
1778 }
1779
1780 #[tokio::test]
1781 async fn wait_returns_when_the_command_exits() {
1782 let workdir = tempfile::tempdir().unwrap();
1783 let runtime = tempfile::tempdir().unwrap();
1784 let (outcome, registry, _receiver) = detached_run(
1785 workdir.path(),
1786 runtime.path(),
1787 "sleep 3; echo done; exit 7",
1788 Duration::from_secs(1),
1789 );
1790 let _guard = KillRunningOnDrop(Arc::clone(®istry));
1791 let info = demoted(outcome);
1792
1793 let waiting = Instant::now();
1794 let end = registry
1795 .wait(
1796 &info.work_id,
1797 crate::background_command::effective_wait(Some(30)),
1798 None,
1799 )
1800 .await;
1801 let waited = waiting.elapsed();
1802 assert_eq!(end, WaitEnd::Finished);
1803 assert!(waited < Duration::from_secs(6), "the wait took {waited:?}");
1804 let (snapshot, result) = read_text(®istry, &info.work_id, Some(waited));
1805 let data = result.data.unwrap();
1806 assert_eq!(snapshot.state, CommandState::Exited);
1807 for line in ["state: exited\n", "exit_code: 7\n", "status: error\n"] {
1808 assert!(data.contains(line), "{line}: {data}");
1809 }
1810 assert!(data.ends_with("\n\ndone\n"), "{data}");
1811 assert!(registry.exit_reported(&info.work_id));
1812 }
1813
1814 fn registry_holding(work_id: &str) -> Arc<DetachedRegistry> {
1819 let (registry, _receiver) = DetachedRegistry::new();
1820 registry.register(
1821 DetachedWork {
1822 work_id: work_id.to_string(),
1823 binary: "/usr/bin/bash".to_string(),
1824 command: "sleep 3".to_string(),
1825 started_at_ms: 1_000,
1826 },
1827 Instant::now(),
1828 0,
1829 format!("/records/logs/{work_id}.log"),
1830 Arc::new(Mutex::new(LiveOutput {
1831 file: None,
1832 tail: VecDeque::new(),
1833 section_bytes: 0,
1834 write_error: None,
1835 })),
1836 );
1837 registry
1838 }
1839
1840 fn completion_of(work_id: &str) -> DetachedCompletion {
1841 DetachedCompletion {
1842 work_id: work_id.to_string(),
1843 binary: "/usr/bin/bash".to_string(),
1844 command: "sleep 3".to_string(),
1845 exit_code: 0,
1846 duration_ms: 3_000,
1847 exited_at_ms: 4_000,
1848 output_path: format!("/records/logs/{work_id}.log"),
1849 output_bytes: 0,
1850 resource_limit: None,
1851 output_holders: crate::shell::OutputHolders::Closed,
1852 context_id: "ctx_1".to_string(),
1853 provenance: completion_provenance(),
1854 error: None,
1855 }
1856 }
1857
1858 #[test]
1862 fn a_read_claims_a_finished_command_before_the_task_loop_does() {
1863 let registry = registry_holding("wrk_read");
1864 registry.complete(completion_of("wrk_read"));
1865
1866 let first = registry.read("wrk_read").unwrap();
1867 assert_eq!(first.state, CommandState::Exited);
1868 assert!(first.delivered_now, "the first read of the exit claims it");
1869 assert!(
1870 !registry.read("wrk_read").unwrap().delivered_now,
1871 "a second read claims nothing"
1872 );
1873 assert!(registry.exit_reported("wrk_read"));
1874 assert!(
1875 !registry.claim_for_task("wrk_read"),
1876 "the task loop finds the completion already delivered"
1877 );
1878 }
1879
1880 #[test]
1882 fn the_task_loop_claims_a_completion_no_read_has_delivered() {
1883 let registry = registry_holding("wrk_task");
1884 registry.complete(completion_of("wrk_task"));
1885
1886 assert!(registry.claim_for_task("wrk_task"));
1887 assert!(!registry.claim_for_task("wrk_task"), "claimed once");
1888 let read = registry.read("wrk_task").unwrap();
1889 assert_eq!(read.state, CommandState::Exited);
1890 assert!(
1891 !read.delivered_now,
1892 "the queued task delivers it, not the read"
1893 );
1894 assert!(
1895 !registry.exit_reported("wrk_task"),
1896 "a task delivery is not a background-command one"
1897 );
1898 }
1899
1900 #[test]
1902 fn a_read_of_a_running_command_claims_nothing() {
1903 let registry = registry_holding("wrk_running");
1904 let read = registry.read("wrk_running").unwrap();
1905 assert_eq!(read.state, CommandState::Running);
1906 assert!(!read.delivered_now);
1907 assert!(!registry.exit_reported("wrk_running"));
1908
1909 registry.complete(completion_of("wrk_running"));
1910 assert!(registry.read("wrk_running").unwrap().delivered_now);
1911 }
1912
1913 #[test]
1916 fn exited_at_ms_is_stamped_at_the_exit_not_at_the_read() {
1917 let workdir = tempfile::tempdir().unwrap();
1918 let runtime = tempfile::tempdir().unwrap();
1919 let before = crate::trace::timestamp_ms();
1920 let (outcome, registry, mut receiver) = detached_run(
1921 workdir.path(),
1922 runtime.path(),
1923 "sleep 2; exit 3",
1924 Duration::from_millis(500),
1925 );
1926 let _guard = KillRunningOnDrop(Arc::clone(®istry));
1927 let info = demoted(outcome);
1928
1929 let completion = await_completion(&mut receiver);
1930 let received = crate::trace::timestamp_ms();
1931 assert!(
1932 completion.exited_at_ms >= before + 2_000 && completion.exited_at_ms <= received,
1933 "exited at {} for a command started after {before} and received at {received}",
1934 completion.exited_at_ms
1935 );
1936
1937 std::thread::sleep(Duration::from_millis(400));
1938 let read = registry.read(&info.work_id).unwrap();
1939 assert!(read.delivered_now);
1940 assert_eq!(
1941 read.finished.unwrap().exited_at_ms,
1942 completion.exited_at_ms,
1943 "the read hands back the exit time the command's thread stamped"
1944 );
1945 }
1946
1947 #[tokio::test]
1948 async fn wait_returns_at_its_bound_with_the_command_still_running() {
1949 let workdir = tempfile::tempdir().unwrap();
1950 let runtime = tempfile::tempdir().unwrap();
1951 let (outcome, registry, _receiver) = detached_run(
1952 workdir.path(),
1953 runtime.path(),
1954 "sleep 60",
1955 Duration::from_secs(1),
1956 );
1957 let _guard = KillRunningOnDrop(Arc::clone(®istry));
1958 let info = demoted(outcome);
1959
1960 let waiting = Instant::now();
1961 let end = registry
1962 .wait(
1963 &info.work_id,
1964 crate::background_command::effective_wait(Some(1)),
1965 None,
1966 )
1967 .await;
1968 let waited = waiting.elapsed();
1969 assert_eq!(end, WaitEnd::TimedOut);
1970 assert!(
1971 waited >= Duration::from_secs(1) && waited < Duration::from_secs(3),
1972 "the wait took {waited:?}"
1973 );
1974 let (snapshot, result) = read_text(®istry, &info.work_id, Some(waited));
1975 let data = result.data.unwrap();
1976 assert_eq!(snapshot.state, CommandState::Running);
1977 assert!(data.contains("waited_secs: 1\n"), "{data}");
1978 assert!(!data.contains("exit_code"), "{data}");
1979 assert!(!registry.exit_reported(&info.work_id));
1980 }
1981
1982 #[tokio::test]
1985 async fn stop_ends_the_command_and_its_children() {
1986 let workdir = tempfile::tempdir().unwrap();
1987 let runtime = tempfile::tempdir().unwrap();
1988 let _leader = KillPidFileOnDrop(workdir.path().join("leader.pid"));
1989 let _child = KillPidFileOnDrop(workdir.path().join("child.pid"));
1990 let (outcome, registry, _receiver) = detached_run(
1991 workdir.path(),
1992 runtime.path(),
1993 "echo $$ > leader.pid; sleep 300 > /dev/null 2>&1 & echo $! > child.pid; sleep 300",
1994 Duration::from_secs(1),
1995 );
1996 let _guard = KillRunningOnDrop(Arc::clone(®istry));
1997 let info = demoted(outcome);
1998
1999 let stopping = Instant::now();
2000 assert!(registry.stop(&info.work_id).await);
2001 let took = stopping.elapsed();
2002 assert!(took < Duration::from_secs(5), "the stop took {took:?}");
2003 let (snapshot, result) = read_text(®istry, &info.work_id, None);
2004 let data = result.data.unwrap();
2005 assert_eq!(snapshot.state, CommandState::Stopped, "{data}");
2006 let exit_code = snapshot.finished.as_ref().unwrap().exit_code;
2007 assert!([143, 137].contains(&exit_code), "{data}");
2008 assert!(data.contains("state: stopped\n"), "{data}");
2009 assert_eq!(snapshot.finished.unwrap().resource_limit, None);
2010 for file in ["leader.pid", "child.pid"] {
2011 let pid = read_pid(&workdir.path().join(file));
2012 assert!(
2013 process_dead_within(pid, Duration::from_secs(2)),
2014 "{file}'s process {pid} is still running"
2015 );
2016 }
2017 }
2018
2019 #[tokio::test]
2021 async fn stop_escalates_to_sigkill_when_sigterm_is_ignored() {
2022 let workdir = tempfile::tempdir().unwrap();
2023 let runtime = tempfile::tempdir().unwrap();
2024 let _leader = KillPidFileOnDrop(workdir.path().join("leader.pid"));
2025 let (outcome, registry, _receiver) = detached_run(
2026 workdir.path(),
2027 runtime.path(),
2028 "echo $$ > leader.pid; trap '' TERM; while :; do sleep 1; done",
2029 Duration::from_secs(1),
2030 );
2031 let _guard = KillRunningOnDrop(Arc::clone(®istry));
2032 let info = demoted(outcome);
2033
2034 let stopping = Instant::now();
2035 assert!(registry.stop(&info.work_id).await);
2036 let took = stopping.elapsed();
2037 assert!(took < Duration::from_secs(5), "the stop took {took:?}");
2038 assert!(
2039 took >= crate::background_command::STOP_TERM_GRACE,
2040 "{took:?}"
2041 );
2042 let (snapshot, result) = read_text(®istry, &info.work_id, None);
2043 assert_eq!(snapshot.state, CommandState::Stopped, "{:?}", result.data);
2044 assert_eq!(snapshot.finished.unwrap().exit_code, 137);
2045 assert_eq!(registry.signals_sent(&info.work_id), 2);
2046 let pid = read_pid(&workdir.path().join("leader.pid"));
2047 assert!(
2048 process_dead_within(pid, Duration::from_secs(2)),
2049 "{pid} still runs"
2050 );
2051 }
2052
2053 #[tokio::test]
2055 async fn stop_on_a_finished_command_reports_it_unchanged() {
2056 let workdir = tempfile::tempdir().unwrap();
2057 let runtime = tempfile::tempdir().unwrap();
2058 let (outcome, registry, mut receiver) = detached_run(
2059 workdir.path(),
2060 runtime.path(),
2061 "sleep 1.5; exit 0",
2062 Duration::from_secs(1),
2063 );
2064 let info = demoted(outcome);
2065 await_completion(&mut receiver);
2066
2067 assert!(registry.stop(&info.work_id).await);
2068 let (snapshot, result) = read_text(®istry, &info.work_id, None);
2069 let data = result.data.unwrap();
2070 assert_eq!(snapshot.state, CommandState::Exited, "{data}");
2071 assert!(data.contains("exit_code: 0\nstatus: ok\n"), "{data}");
2072 assert_eq!(registry.signals_sent(&info.work_id), 0);
2073 assert!(
2074 !registry.stop(&new_work_id()).await,
2075 "an unknown id is not stopped"
2076 );
2077 }
2078
2079 #[test]
2082 fn kill_running_leaves_nothing_without_a_cgroup_scope() {
2083 let workdir = tempfile::tempdir().unwrap();
2084 let runtime = tempfile::tempdir().unwrap();
2085 let _leader = KillPidFileOnDrop(workdir.path().join("leader.pid"));
2086 let _child = KillPidFileOnDrop(workdir.path().join("child.pid"));
2087 let enforcement = ShellEnforcement::environment_only()
2088 .with_runtime_dir(crate::sandbox::test_runtime_dir(runtime.path()), None);
2089 assert!(enforcement.cgroup_scope.is_none());
2090 let (outcome, registry, _receiver) = detached_run_with(
2091 workdir.path(),
2092 &enforcement,
2093 "echo $$ > leader.pid; sleep 300 > /dev/null 2>&1 & echo $! > child.pid; sleep 300",
2094 Duration::from_secs(1),
2095 );
2096 let info = demoted(outcome);
2097 assert_eq!(registry.outstanding().len(), 1);
2098
2099 registry.kill_running();
2100 for file in ["leader.pid", "child.pid"] {
2101 let pid = read_pid(&workdir.path().join(file));
2102 assert!(
2103 process_dead_within(pid, Duration::from_secs(2)),
2104 "{file}'s process {pid} outlived kill_running"
2105 );
2106 }
2107 assert_eq!(registry.signals_sent(&info.work_id), 1);
2108 }
2109
2110 #[test]
2113 fn the_demotion_result_is_a_constant_size() {
2114 for delivered in [true, false] {
2115 for tool_offered in [true, false] {
2116 the_demotion_result_is_a_constant_size_when(delivered, tool_offered);
2117 }
2118 }
2119 }
2120
2121 fn the_demotion_result_is_a_constant_size_when(delivered: bool, tool_offered: bool) {
2122 let reduce = |work_id: &str| {
2123 let result = demotion_tool_result(work_id, delivered, tool_offered);
2124 result
2125 .data
2126 .or(result.summary)
2127 .unwrap_or_else(|| "tool returned no data".to_string())
2128 };
2129 let first = reduce(&new_work_id());
2130 let second = reduce(&new_work_id());
2131
2132 assert_eq!(
2133 first.len(),
2134 second.len(),
2135 "two work ids of equal length must produce texts of equal size"
2136 );
2137 for text in [&first, &second] {
2141 let tokens = crate::agent::count_tokens(text);
2142 assert!(
2143 tokens < 120,
2144 "the demotion result costs {tokens} tokens, over the 120-token ceiling"
2145 );
2146 }
2147 assert!(
2148 !first.contains("logs/"),
2149 "the demotion result names no path: {first}"
2150 );
2151 }
2152
2153 fn still_running(work_id: &str, running_ms: u64) -> AbandonedWork {
2156 AbandonedWork {
2157 work_id: work_id.to_string(),
2158 binary: "/usr/bin/bash".to_string(),
2159 command: "sleep 45; echo done".to_string(),
2160 disposition: AbandonedDisposition::StillRunning { running_ms },
2161 }
2162 }
2163
2164 fn report_records() -> (tempfile::TempDir, crate::workdir_fs::WorkdirRoot) {
2166 let dir = tempfile::tempdir().unwrap();
2167 let root = crate::workdir_fs::WorkdirRoot::open(dir.path()).unwrap();
2168 (dir, root)
2169 }
2170
2171 fn finished_too_late(
2172 records_root: &crate::workdir_fs::WorkdirRoot,
2173 work_id: &str,
2174 ) -> AbandonedWork {
2175 AbandonedWork {
2176 work_id: work_id.to_string(),
2177 binary: "/usr/bin/bash".to_string(),
2178 command: "sleep 2; echo done".to_string(),
2179 disposition: AbandonedDisposition::FinishedTooLate {
2180 exit_code: 0,
2181 duration_ms: 2_014,
2182 output_path: output_path_for(records_root, work_id).path,
2183 output_bytes: 91,
2184 resource_limit: None,
2185 wait_error: None,
2186 status: "ok",
2187 },
2188 }
2189 }
2190
2191 #[test]
2195 fn a_still_running_command_is_reported_as_killed_with_what_is_known() {
2196 let (records, records_root) = report_records();
2197 let text = abandonment_report_text(
2198 "ses_abc",
2199 &records_root,
2200 &[still_running("wrk_0a1b", 45_012)],
2201 );
2202
2203 assert!(
2204 text.contains("1 background shell command discarded"),
2205 "{text}"
2206 );
2207 assert!(text.contains("Session ses_abc"), "{text}");
2208 assert!(text.contains("work_id: wrk_0a1b"), "{text}");
2209 assert!(text.contains("binary: /usr/bin/bash"), "{text}");
2210 assert!(text.contains("command: sleep 45; echo done"), "{text}");
2211 assert!(
2212 text.contains("state: killed at session end after 45012 ms"),
2213 "{text}"
2214 );
2215 let path = records.path().join("logs/wrk_0a1b.log");
2216 assert!(
2217 text.contains(&format!("before the kill is in {}.", path.display())),
2218 "the report names the log by its absolute path: {text}"
2219 );
2220 assert!(!text.contains("exit_code:"), "no exit code exists: {text}");
2221 for retired in [
2222 "nothing was killed",
2223 "Nothing was waited for",
2224 "keeps running",
2225 ] {
2226 assert!(
2227 !text.contains(retired),
2228 "the session's end kills what it started, so the report must not say {retired:?}: \
2229 {text}"
2230 );
2231 }
2232 }
2233
2234 #[test]
2238 fn a_command_that_finished_during_teardown_is_reported_with_its_result() {
2239 let (records, records_root) = report_records();
2240 let text = abandonment_report_text(
2241 "ses_abc",
2242 &records_root,
2243 &[finished_too_late(&records_root, "wrk_0c2d")],
2244 );
2245
2246 assert!(
2247 text.contains("state: finished during teardown after 2014 ms"),
2248 "{text}"
2249 );
2250 assert!(text.contains("status: ok"), "{text}");
2251 assert!(text.contains("exit_code: 0"), "{text}");
2252 let path = records.path().join("logs/wrk_0c2d.log");
2253 assert!(
2254 text.contains(&format!("output: {} (91 bytes)\n", path.display())),
2255 "{text}"
2256 );
2257 assert!(!text.contains("in the capsule workdir"), "{text}");
2258 assert!(!text.contains("killed at session end"), "{text}");
2259 }
2260
2261 #[test]
2264 fn the_report_states_the_condition_once_and_enumerates_every_command() {
2265 let (_records, records_root) = report_records();
2266 let text = abandonment_report_text(
2267 "ses_abc",
2268 &records_root,
2269 &[
2270 still_running("wrk_0a1b", 12),
2271 finished_too_late(&records_root, "wrk_0c2d"),
2272 ],
2273 );
2274
2275 assert_eq!(
2276 text.matches("2 background shell commands discarded")
2277 .count(),
2278 1
2279 );
2280 assert_eq!(text.matches("work_id: ").count(), 2);
2281 assert!(text.contains("wrk_0a1b"), "{text}");
2282 assert!(text.contains("wrk_0c2d"), "{text}");
2283 }
2284
2285 #[test]
2288 fn an_attributed_resource_limit_is_named_in_the_report() {
2289 let (_records, records_root) = report_records();
2290 let mut work = finished_too_late(&records_root, "wrk_0c2d");
2291 if let AbandonedDisposition::FinishedTooLate {
2292 resource_limit,
2293 exit_code,
2294 status,
2295 ..
2296 } = &mut work.disposition
2297 {
2298 *resource_limit = Some("memory".to_string());
2299 *exit_code = 137;
2300 *status = "error";
2301 }
2302 let text = abandonment_report_text("ses_abc", &records_root, &[work]);
2303
2304 assert!(text.contains("resource_limit: memory"), "{text}");
2305 assert!(text.contains("status: error"), "{text}");
2306 assert!(text.contains("exit_code: 137"), "{text}");
2307 }
2308
2309 #[test]
2312 fn only_a_command_that_finished_carries_a_recovered_result() {
2313 assert_eq!(still_running("wrk_0a1b", 45_012).running_ms(), 45_012);
2314 assert!(still_running("wrk_0a1b", 45_012).recovered().is_none());
2315
2316 let (records, records_root) = report_records();
2317 let finished = finished_too_late(&records_root, "wrk_0c2d");
2318 let path = records.path().join("logs/wrk_0c2d.log");
2319 assert_eq!(finished.running_ms(), 2_014);
2320 assert_eq!(
2321 finished.recovered(),
2322 Some((0, path.to_str().unwrap(), 91)),
2323 "the exit code, the output path and its byte count travel together"
2324 );
2325 }
2326
2327 #[test]
2331 fn a_failed_wait_is_named_beside_the_status_it_explains() {
2332 let (_records, records_root) = report_records();
2333 let mut work = finished_too_late(&records_root, "wrk_0c2d");
2334 if let AbandonedDisposition::FinishedTooLate {
2335 wait_error, status, ..
2336 } = &mut work.disposition
2337 {
2338 *wait_error = Some("no child processes".to_string());
2339 *status = "error";
2340 }
2341 let text = abandonment_report_text("ses_abc", &records_root, &[work]);
2342
2343 assert!(text.contains("status: error"), "{text}");
2344 assert!(text.contains("wait_error: no child processes"), "{text}");
2345 }
2346
2347 #[test]
2350 fn the_report_does_not_claim_nothing_is_recoverable() {
2351 let (_records, records_root) = report_records();
2352 let text =
2353 abandonment_report_text("ses_abc", &records_root, &[still_running("wrk_0a1b", 12)]);
2354 assert!(
2355 !text.contains("No exit code was recorded"),
2356 "the clean-exit report is not the crash report: {text}"
2357 );
2358 }
2359}