start_command/
detached_finalize.rs

1//! Detached completion finalizer (issue #170).
2//!
3//! A detached Docker session outlives the CLI process that started it: the
4//! foreground `start` invocation returns as soon as the container is up, so
5//! nobody is left to write the terminal state back into the execution store.
6//! The record therefore stayed `executing` forever, with `exitCode: null` and
7//! `endTime: null`, and every `--status` query had to re-derive the outcome from
8//! scratch — fabricating `endTime` with the current time in the process.
9//!
10//! The detached completion watcher (see `docker_cleanup`) now re-invokes the
11//! `start` binary with a hidden flag once the container is gone, handing over
12//! the facts it already read out of a single `docker inspect`. The finalizer is
13//! deliberately silent and infallible: it is a short-lived child process on a
14//! host whose CLI invocation is long gone, so a bookkeeping failure must never
15//! surface as an error in a log the user is reading for the command's output.
16
17use std::path::PathBuf;
18
19use chrono::Utc;
20use serde_json::Value;
21
22use crate::docker_post_mortem::{normalize_docker_timestamp, shell_vars};
23use crate::execution_store::{
24    ExecutionRecord, ExecutionStatus, ExecutionStore, ExecutionStoreOptions,
25};
26use crate::exit_reason::{describe_exit_code_str, resolve_exit_reason};
27use crate::isolation::isolation_log::{read_log_tail, shell_quote, FATAL_MARKER_TAIL_BYTES};
28
29/// Hidden argument the detached watcher re-invokes this binary with.
30/// Not part of the public CLI surface: it is an implementation detail of the
31/// watcher, and `--help` stays free of it.
32pub const INTERNAL_FINALIZE_FLAG: &str = "--internal-finalize-detached-docker";
33
34/// `end_time` came from `docker inspect .State.FinishedAt` — the container's
35/// own clock, the only real finish time available.
36pub const END_TIME_SOURCE_DOCKER_FINISHED_AT: &str = "docker-finished-at";
37/// `end_time` came from the anchored `Finished:` line `start` itself wrote.
38pub const END_TIME_SOURCE_LOG_FOOTER: &str = "log-footer";
39/// No real finish time exists: this is when the end was *observed*.
40pub const END_TIME_SOURCE_OBSERVED_AT: &str = "observed-at";
41
42/// `exit_reason` of a record whose container exit the watcher never observed:
43/// docker had no `FinishedAt` for it, so neither the exit code nor the end time
44/// is a fact (issue #174).
45pub const WATCHER_LOST_CONTAINER: &str = "watcher-lost-container";
46
47/// The docker facts the watcher hands over.
48#[derive(Debug, Clone, Default)]
49pub struct DetachedFinalizeFacts {
50    pub exit_code: String,
51    pub oom_killed: String,
52    pub started_at: String,
53    pub finished_at: String,
54    pub container_error: String,
55    /// `.State.Running`: `true` means the container has not exited (issue #174).
56    pub running: String,
57}
58
59/// Outcome of a finalization attempt. `updated` is false when there was
60/// nothing to correct (or nothing to correct it on).
61#[derive(Debug, Clone, PartialEq, Eq)]
62pub struct FinalizeOutcome {
63    pub updated: bool,
64    pub reason: String,
65}
66
67fn normalize_bool(value: &str) -> Option<bool> {
68    match value.trim() {
69        "true" => Some(true),
70        "false" => Some(false),
71        _ => None,
72    }
73}
74
75fn normalize_container_error(value: &str) -> Option<String> {
76    let trimmed = value.trim();
77    if trimmed.is_empty() || trimmed == "<no value>" || trimmed == "(none)" {
78        None
79    } else {
80        Some(trimmed.to_string())
81    }
82}
83
84/// Persist the terminal state of a detached execution.
85///
86/// Purely additive with respect to the observation-vs-verdict discipline of
87/// issues #148/#151/#162: `oom_killed` and `exit_reason` are recorded as facts
88/// next to the exit code, never as a substitute for it.
89pub fn finalize_detached_execution(
90    store: &ExecutionStore,
91    execution_id: &str,
92    facts: &DetachedFinalizeFacts,
93) -> FinalizeOutcome {
94    if execution_id.is_empty() {
95        return FinalizeOutcome {
96            updated: false,
97            reason: "missing-arguments".to_string(),
98        };
99    }
100    if normalize_bool(&facts.running) == Some(true) {
101        // A running container has not finished: its record stays `executing`,
102        // and `--status` keeps probing the live container (issue #174).
103        return FinalizeOutcome {
104            updated: false,
105            reason: "still-running".to_string(),
106        };
107    }
108    let mut record = match store.get(execution_id) {
109        Some(record) => record,
110        None => {
111            return FinalizeOutcome {
112                updated: false,
113                reason: "record-not-found".to_string(),
114            }
115        }
116    };
117    if record.status == ExecutionStatus::Executed && record.end_time.is_some() {
118        // Already finalized (e.g. a `--status` query got there first, or the
119        // watcher ran twice after a resume). Nothing to correct.
120        return FinalizeOutcome {
121            updated: false,
122            reason: "already-final".to_string(),
123        };
124    }
125
126    let finished_at = normalize_docker_timestamp(Some(&facts.finished_at));
127    let described = describe_exit_code_str(&facts.exit_code);
128    // Without a `FinishedAt`, `ExitCode=0` is Docker's zero value for a container
129    // that has not finished — never an observed success (issue #174).
130    let exit_code = match described.code {
131        Some(0) if finished_at.is_none() => None,
132        code => code,
133    };
134    record.status = ExecutionStatus::Executed;
135    match exit_code {
136        Some(code) => record.exit_code = Some(code),
137        None => {
138            if record.exit_code.is_none() || finished_at.is_none() {
139                record.exit_code = Some(-1);
140            }
141        }
142    }
143    let lost = finished_at.is_none();
144
145    match finished_at {
146        Some(finished_at) => {
147            record.end_time = Some(finished_at);
148            record.end_time_source = Some(END_TIME_SOURCE_DOCKER_FINISHED_AT.to_string());
149        }
150        None => {
151            // Docker has no finish time for this container (it never started, or
152            // it was removed before we could look). Record *when we noticed*,
153            // and say so, rather than passing observation time off as a finish
154            // time (issue #170.2).
155            let now = Utc::now().to_rfc3339();
156            record.end_time = Some(now.clone());
157            record.end_time_source = Some(END_TIME_SOURCE_OBSERVED_AT.to_string());
158            record.observed_at = Some(now);
159        }
160    }
161
162    if let Some(started_at) = normalize_docker_timestamp(Some(&facts.started_at)) {
163        record.container_started_at = Some(started_at);
164    }
165    if let Some(oom_killed) = normalize_bool(&facts.oom_killed) {
166        record.oom_killed = Some(oom_killed);
167    }
168    let reason =
169        resolve_reason(&record).or_else(|| lost.then(|| WATCHER_LOST_CONTAINER.to_string()));
170    if let Some(reason) = reason {
171        record.exit_reason = Some(reason);
172    }
173    if let Some(error) = normalize_container_error(&facts.container_error) {
174        record
175            .options
176            .insert("containerError".to_string(), Value::String(error));
177    }
178
179    match store.save(&record) {
180        Ok(()) => FinalizeOutcome {
181            updated: true,
182            reason: "finalized".to_string(),
183        },
184        Err(error) => FinalizeOutcome {
185            updated: false,
186            reason: format!("save-failed: {}", error),
187        },
188    }
189}
190
191/// Derive the `exit_reason` hint from the same evidence `--status` would use.
192fn resolve_reason(record: &ExecutionRecord) -> Option<String> {
193    let tail = if record.log_path.is_empty() {
194        None
195    } else {
196        read_log_tail(&record.log_path, FATAL_MARKER_TAIL_BYTES)
197    };
198    resolve_exit_reason(record.exit_code, tail.as_deref(), record.oom_killed)
199}
200
201/// Reconcile an in-memory record with one the detached watcher already
202/// finalized.
203///
204/// A container that exits almost immediately can be finalized by the watcher
205/// before the foreground `start` invocation writes its own last update. Saving
206/// the stale in-memory copy would resurrect `status: executing` and throw the
207/// terminal facts away, so the stored record wins and only the fields the
208/// foreground process learned (its `options`, e.g. `containerId`) are merged in.
209pub fn reconcile_finalized_record(
210    store: &ExecutionStore,
211    record: &ExecutionRecord,
212) -> ExecutionRecord {
213    let stored = match store.get(&record.uuid) {
214        Some(stored) => stored,
215        None => return record.clone(),
216    };
217    if stored.status != ExecutionStatus::Executed || stored.end_time.is_none() {
218        return record.clone();
219    }
220    let mut merged = stored;
221    for (key, value) in &record.options {
222        merged.options.insert(key.clone(), value.clone());
223    }
224    merged
225}
226
227/// Shell fragment that hands the inspected docker facts to this finalizer.
228///
229/// Runs the same binary that started the session and is suffixed with
230/// `|| true`, so a finalization failure can never abort the watcher's remaining
231/// cleanup work.
232pub fn build_detached_finalize_snippet(execution_id: &str) -> String {
233    let executable = std::env::current_exe()
234        .map(|path| path.to_string_lossy().to_string())
235        .unwrap_or_else(|_| "start".to_string());
236    format!(
237        "{} {} {} \"${}\" \"${}\" \"${}\" \"${}\" \"${}\" \"${}\" >/dev/null 2>&1 || true",
238        shell_quote(&executable),
239        INTERNAL_FINALIZE_FLAG,
240        shell_quote(execution_id),
241        shell_vars::EXIT,
242        shell_vars::OOM,
243        shell_vars::STARTED,
244        shell_vars::FINISHED,
245        shell_vars::ERROR,
246        shell_vars::RUNNING,
247    )
248}
249
250/// Entry point for `--internal-finalize-detached-docker <uuid> <exit> <oom>
251/// <started> <finished> <error> <running>`. Always succeeds: see the module docs.
252pub fn run_internal_finalize(args: &[String]) {
253    let execution_id = match args.first() {
254        Some(value) if !value.is_empty() => value.clone(),
255        _ => return,
256    };
257    if std::env::var("START_DISABLE_TRACKING").as_deref() == Ok("true") {
258        return;
259    }
260    let field = |index: usize| args.get(index).cloned().unwrap_or_default();
261    let store = ExecutionStore::with_options(ExecutionStoreOptions {
262        app_folder: std::env::var("START_APP_FOLDER").ok().map(PathBuf::from),
263        ..ExecutionStoreOptions::default()
264    });
265    finalize_detached_execution(
266        &store,
267        &execution_id,
268        &DetachedFinalizeFacts {
269            exit_code: field(1),
270            oom_killed: field(2),
271            started_at: field(3),
272            finished_at: field(4),
273            container_error: field(5),
274            running: field(6),
275        },
276    );
277}
start_command/detached_finalize.rs

start_command/
detached_finalize.rs
