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::cgroup_memory::{cgroup_shell_vars, parse_cgroup_memory_sample};
23use crate::container_removal::{
24    mark_container_removed, CONTAINER_REMOVED_ENV, CONTAINER_STATE_REMOVED,
25};
26use crate::docker_post_mortem::{normalize_docker_timestamp, shell_vars};
27use crate::execution_attempt::{append_lifecycle, read_attempt_activity, read_attempt_log_tail};
28use crate::execution_store::{
29    ExecutionRecord, ExecutionStatus, ExecutionStore, ExecutionStoreOptions,
30};
31use crate::exit_reason::{describe_exit_code_str, resolve_exit_reason};
32use crate::isolation::isolation_log::{shell_quote, FATAL_MARKER_TAIL_BYTES};
33
34/// Hidden argument the detached watcher re-invokes this binary with.
35/// Not part of the public CLI surface: it is an implementation detail of the
36/// watcher, and `--help` stays free of it.
37pub const INTERNAL_FINALIZE_FLAG: &str = "--internal-finalize-detached-docker";
38
39/// `end_time` came from `docker inspect .State.FinishedAt` — the container's
40/// own clock, the only real finish time available.
41pub const END_TIME_SOURCE_DOCKER_FINISHED_AT: &str = "docker-finished-at";
42/// `end_time` came from the anchored `Finished:` line `start` itself wrote.
43pub const END_TIME_SOURCE_LOG_FOOTER: &str = "log-footer";
44/// No real finish time exists: this is when the end was *observed*.
45pub const END_TIME_SOURCE_OBSERVED_AT: &str = "observed-at";
46
47/// `exit_reason` of a record whose container exit the watcher never observed:
48/// docker had no `FinishedAt` for it, so neither the exit code nor the end time
49/// is a fact (issue #174).
50pub const WATCHER_LOST_CONTAINER: &str = "watcher-lost-container";
51
52/// The docker facts the watcher hands over.
53#[derive(Debug, Clone, Default)]
54pub struct DetachedFinalizeFacts {
55    pub exit_code: String,
56    pub oom_killed: String,
57    pub started_at: String,
58    pub finished_at: String,
59    pub container_error: String,
60    /// `.State.Running`: `true` means the container has not exited (issue #174).
61    pub running: String,
62    /// Last cgroup v2 sample of the watcher,
63    /// `<memory.max> <memory.peak> <oom> <oom_kill>` (issue #182).
64    pub cgroup_memory: String,
65}
66
67/// Outcome of a finalization attempt. `updated` is false when there was
68/// nothing to correct (or nothing to correct it on).
69#[derive(Debug, Clone, PartialEq, Eq)]
70pub struct FinalizeOutcome {
71    pub updated: bool,
72    pub reason: String,
73}
74
75pub(crate) fn normalize_bool(value: &str) -> Option<bool> {
76    match value.trim() {
77        "true" => Some(true),
78        "false" => Some(false),
79        _ => None,
80    }
81}
82
83pub(crate) fn normalize_container_error(value: &str) -> Option<String> {
84    let trimmed = value.trim();
85    if trimmed.is_empty() || trimmed == "<no value>" || trimmed == "(none)" {
86        None
87    } else {
88        Some(trimmed.to_string())
89    }
90}
91
92/// Persist the terminal state of a detached execution.
93///
94/// Purely additive with respect to the observation-vs-verdict discipline of
95/// issues #148/#151/#162: `oom_killed` and `exit_reason` are recorded as facts
96/// next to the exit code, never as a substitute for it.
97pub fn finalize_detached_execution(
98    store: &ExecutionStore,
99    execution_id: &str,
100    facts: &DetachedFinalizeFacts,
101) -> FinalizeOutcome {
102    finalize_detached_execution_with_attempt(store, execution_id, facts, None)
103}
104
105pub fn finalize_detached_execution_with_attempt(
106    store: &ExecutionStore,
107    execution_id: &str,
108    facts: &DetachedFinalizeFacts,
109    attempt_number: Option<u64>,
110) -> FinalizeOutcome {
111    finalize_detached_execution_with_removal(store, execution_id, facts, attempt_number, false)
112}
113
114/// Same as [`finalize_detached_execution_with_attempt`]; `container_removed`
115/// says the watcher's own `docker rm -f` removed the container (issue #225).
116pub fn finalize_detached_execution_with_removal(
117    store: &ExecutionStore,
118    execution_id: &str,
119    facts: &DetachedFinalizeFacts,
120    attempt_number: Option<u64>,
121    container_removed: bool,
122) -> FinalizeOutcome {
123    if execution_id.is_empty() {
124        return FinalizeOutcome {
125            updated: false,
126            reason: "missing-arguments".to_string(),
127        };
128    }
129    if normalize_bool(&facts.running) == Some(true) {
130        // A running container has not finished: its record stays `executing`,
131        // and `--status` keeps probing the live container (issue #174).
132        return FinalizeOutcome {
133            updated: false,
134            reason: "still-running".to_string(),
135        };
136    }
137    let mut record = match store.get(execution_id) {
138        Some(record) => record,
139        None => {
140            return FinalizeOutcome {
141                updated: false,
142                reason: "record-not-found".to_string(),
143            }
144        }
145    };
146    if let Some(attempt) = &record.attempt {
147        let started = normalize_docker_timestamp(Some(&facts.started_at));
148        let older = started
149            .as_deref()
150            .and_then(|s| chrono::DateTime::parse_from_rfc3339(s).ok())
151            .zip(chrono::DateTime::parse_from_rfc3339(&attempt.started_at).ok())
152            .is_some_and(|(started, since)| started < since);
153        if attempt_number.is_some_and(|number| number != attempt.number)
154            || older
155            || (attempt_number.is_none() && started.is_none())
156        {
157            return FinalizeOutcome {
158                updated: false,
159                reason: "stale-attempt".into(),
160            };
161        }
162    }
163    if record.status == ExecutionStatus::Executed && record.end_time.is_some() {
164        // Already finalized (e.g. a `--status` query got there first, or the
165        // watcher ran twice after a resume). Only the removal can still be new.
166        if container_removed
167            && record.container_state.as_deref() != Some(CONTAINER_STATE_REMOVED)
168            && matches!(
169                store.mark_container_removed(&record.uuid, &Utc::now().to_rfc3339()),
170                Ok(Some(_))
171            )
172        {
173            return FinalizeOutcome {
174                updated: true,
175                reason: "container-removed".to_string(),
176            };
177        }
178        return FinalizeOutcome {
179            updated: false,
180            reason: "already-final".to_string(),
181        };
182    }
183
184    let finished_at = normalize_docker_timestamp(Some(&facts.finished_at));
185    let described = describe_exit_code_str(&facts.exit_code);
186    // Without a `FinishedAt`, `ExitCode=0` is Docker's zero value for a container
187    // that has not finished — never an observed success (issue #174).
188    let exit_code = match described.code {
189        Some(0) if finished_at.is_none() => None,
190        code => code,
191    };
192    record.status = ExecutionStatus::Executed;
193    match exit_code {
194        Some(code) => record.exit_code = Some(code),
195        None => {
196            if record.exit_code.is_none() || finished_at.is_none() {
197                record.exit_code = Some(-1);
198            }
199        }
200    }
201    let lost = finished_at.is_none();
202
203    match finished_at {
204        Some(finished_at) => {
205            record.end_time = Some(finished_at);
206            record.end_time_source = Some(END_TIME_SOURCE_DOCKER_FINISHED_AT.to_string());
207        }
208        None => {
209            // Docker has no finish time for this container (it never started, or
210            // it was removed before we could look). Record *when we noticed*,
211            // and say so, rather than passing observation time off as a finish
212            // time (issue #170.2).
213            let now = Utc::now().to_rfc3339();
214            record.end_time = Some(now.clone());
215            record.end_time_source = Some(END_TIME_SOURCE_OBSERVED_AT.to_string());
216            record.observed_at = Some(now);
217        }
218    }
219
220    if let Some(started_at) = normalize_docker_timestamp(Some(&facts.started_at)) {
221        record.container_started_at = Some(started_at);
222    }
223    if let Some(oom_killed) = normalize_bool(&facts.oom_killed) {
224        record.oom_killed = Some(oom_killed);
225    }
226    // Counted by the kernel for this run only, unlike the sticky `OOMKilled`.
227    if let Some(cgroup_memory) = parse_cgroup_memory_sample(&facts.cgroup_memory) {
228        record.cgroup_memory = Some(cgroup_memory);
229    }
230    let tail = read_attempt_log_tail(&record, FATAL_MARKER_TAIL_BYTES);
231    let (logged_main, daemon) = crate::exit_evidence::from_log(tail.as_deref());
232    let main = !daemon
233        && (logged_main
234            || (record.oom_killed == Some(true)
235                && record.exit_code.is_some_and(|code| code == 137 || code < 0)
236                && crate::exit_evidence::recent_oom_delta(
237                    &facts.cgroup_memory,
238                    &facts.finished_at,
239                )));
240    record.options.insert(
241        "exitEvidence".into(),
242        crate::exit_evidence::evidence_json(tail.as_deref(), main),
243    );
244    let reason =
245        resolve_reason(&record).or_else(|| lost.then(|| WATCHER_LOST_CONTAINER.to_string()));
246    if let Some(reason) = reason {
247        record.exit_reason = Some(reason);
248    }
249    if let Some(error) = normalize_container_error(&facts.container_error) {
250        record
251            .options
252            .insert("containerError".to_string(), Value::String(error));
253    }
254    if container_removed {
255        // The cleanup policy removed the container: say so, and keep its id as
256        // history (issue #225).
257        mark_container_removed(&mut record, None);
258    }
259
260    read_attempt_activity(&mut record);
261    match store.save(&record) {
262        Ok(()) => {
263            append_lifecycle(
264                &record,
265                "terminal",
266                serde_json::json!({ "status": record.status, "exitCode": record.exit_code,
267                "endTime": record.end_time, "exitReason": record.exit_reason, "oomKilled": record.oom_killed, "cgroupMemory": record.cgroup_memory }),
268            );
269            FinalizeOutcome {
270                updated: true,
271                reason: "finalized".to_string(),
272            }
273        }
274        Err(error) => FinalizeOutcome {
275            updated: false,
276            reason: format!("save-failed: {}", error),
277        },
278    }
279}
280
281/// Derive the `exit_reason` hint from the same evidence `--status` would use.
282fn resolve_reason(record: &ExecutionRecord) -> Option<String> {
283    let tail = if record.log_path.is_empty() {
284        None
285    } else {
286        read_attempt_log_tail(record, FATAL_MARKER_TAIL_BYTES)
287    };
288    let tail = crate::exit_evidence::record_tail(record, tail);
289    resolve_exit_reason(
290        record.exit_code,
291        tail.as_deref(),
292        record.oom_killed,
293        record.cgroup_memory.and_then(|memory| memory.oom_kills),
294    )
295}
296
297/// Reconcile an in-memory record with one the detached watcher already
298/// finalized.
299///
300/// A container that exits almost immediately can be finalized by the watcher
301/// before the foreground `start` invocation writes its own last update. Saving
302/// the stale in-memory copy would resurrect `status: executing` and throw the
303/// terminal facts away, so the stored record wins and only the fields the
304/// foreground process learned (its `options`, e.g. `containerId`) are merged in.
305pub fn reconcile_finalized_record(
306    store: &ExecutionStore,
307    record: &ExecutionRecord,
308) -> ExecutionRecord {
309    let stored = match store.get(&record.uuid) {
310        Some(stored) => stored,
311        None => return record.clone(),
312    };
313    if stored.status != ExecutionStatus::Executed || stored.end_time.is_none() {
314        return record.clone();
315    }
316    let mut merged = stored;
317    for (key, value) in &record.options {
318        merged.options.insert(key.clone(), value.clone());
319    }
320    merged
321}
322
323/// Shell fragment that hands the inspected docker facts to this finalizer.
324///
325/// Runs the same binary that started the session and is suffixed with
326/// `|| true`, so a finalization failure can never abort the watcher's remaining
327/// cleanup work.
328pub fn build_detached_finalize_snippet(execution_id: &str) -> String {
329    build_detached_finalize_snippet_with_attempt(execution_id, None)
330}
331
332pub fn build_detached_finalize_snippet_with_attempt(
333    execution_id: &str,
334    attempt_number: Option<u64>,
335) -> String {
336    let executable = std::env::current_exe()
337        .map(|path| path.to_string_lossy().to_string())
338        .unwrap_or_else(|_| "start".to_string());
339    format!(
340        "{}=\"${}\" {} {} {} \"${}\" \"${}\" \"${}\" \"${}\" \"${}\" \"${}\" \"${}\"{} >/dev/null 2>&1 || true",
341        CONTAINER_REMOVED_ENV,
342        shell_vars::REMOVED,
343        shell_quote(&executable),
344        INTERNAL_FINALIZE_FLAG,
345        shell_quote(execution_id),
346        shell_vars::EXIT,
347        shell_vars::OOM,
348        shell_vars::STARTED,
349        shell_vars::FINISHED,
350        shell_vars::ERROR,
351        shell_vars::RUNNING,
352        cgroup_shell_vars::SAMPLE,
353        attempt_number.map(|number| format!(" {}", shell_quote(&number.to_string()))).unwrap_or_default(),
354    )
355}
356
357/// Entry point for `--internal-finalize-detached-docker <uuid> <exit> <oom>
358/// <started> <finished> <error> <running> <cgroup> [attempt]`, with
359/// `START_INTERNAL_CONTAINER_REMOVED=true` when the watcher removed the
360/// container (issue #225). Always succeeds: see the module docs.
361pub fn run_internal_finalize(args: &[String]) {
362    let execution_id = match args.first() {
363        Some(value) if !value.is_empty() => value.clone(),
364        _ => return,
365    };
366    if std::env::var("START_DISABLE_TRACKING").as_deref() == Ok("true") {
367        return;
368    }
369    let field = |index: usize| args.get(index).cloned().unwrap_or_default();
370    let store = ExecutionStore::with_options(ExecutionStoreOptions {
371        app_folder: std::env::var("START_APP_FOLDER").ok().map(PathBuf::from),
372        ..ExecutionStoreOptions::default()
373    });
374    finalize_detached_execution_with_removal(
375        &store,
376        &execution_id,
377        &DetachedFinalizeFacts {
378            exit_code: field(1),
379            oom_killed: field(2),
380            started_at: field(3),
381            finished_at: field(4),
382            container_error: field(5),
383            running: field(6),
384            cgroup_memory: field(7),
385        },
386        field(8).parse().ok(),
387        std::env::var(CONTAINER_REMOVED_ENV)
388            .is_ok_and(|value| normalize_bool(&value) == Some(true)),
389    );
390}
start_command/detached_finalize.rs

start_command/
detached_finalize.rs
