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

start_command/
detached_finalize.rs
