start_command/
docker_post_mortem.rs

1//! Container post-mortem facts (issues #170, #171).
2//!
3//! When a detached container dies the only thing `start` used to write into the
4//! log was `Reason: exitCode=137 oomKilled=false` — the two facts that, together,
5//! say the least. `137` is `128 + 9`, i.e. SIGKILL, and `oomKilled=false` rules
6//! out the cgroup OOM killer, so the container was killed from the outside
7//! (`docker kill`, a `docker stop` escalation, systemd, the CI runner). None of
8//! that was said out loud, and the three fields that would have shown *when* it
9//! happened — `State.StartedAt`, `State.FinishedAt`, `State.Error` — were never
10//! read at all, even though the watcher was already one `docker inspect` away
11//! from them.
12//!
13//! This module owns those facts in one place:
14//! - `describe_exit_code()` (re-exported from `exit_reason`) decodes `128 + n`
15//!   once, for the watcher (completion time, written into the log) and for
16//!   `--status` (query time, in memory), so the two can never disagree;
17//! - the `build_*_snippet()` helpers generate the POSIX shell the detached
18//!   watcher runs, including the signal table, so the shell and the runtime
19//!   share a single source of truth;
20//! - `format_container_post_mortem()` renders the same block for callers that
21//!   already hold the facts in memory (the attached docker path).
22
23use chrono::{DateTime, Utc};
24
25use crate::exit_reason::{describe_exit_code, SIGNAL_NAMES, UNKNOWN_EXIT_CODE};
26use crate::isolation::isolation_log::shell_quote;
27
28/// Docker's zero value for a timestamp that was never set. `State.FinishedAt`
29/// carries it for every container that has not finished, and `State.StartedAt`
30/// for every container that never started. It must never reach a record as an
31/// `endTime`: a year-1 timestamp is worse than an honest `null`.
32pub const DOCKER_ZERO_TIME: &str = "0001-01-01T00:00:00Z";
33
34/// Placeholder written instead of a fact that could not be observed.
35pub const UNKNOWN: &str = UNKNOWN_EXIT_CODE;
36
37/// Placeholder for `State.Error` when docker reported no error at all.
38pub const NO_ERROR: &str = "(none)";
39
40/// Header line of the post-mortem block appended to a kept container's log.
41pub const POST_MORTEM_HEADER: &str = "=== Container post-mortem ===";
42
43/// `docker inspect -f` template collecting every post-mortem fact at once.
44pub const DOCKER_STATE_INSPECT_FORMAT: &str =
45    "{{.State.ExitCode}} {{.State.OOMKilled}} {{.State.StartedAt}} {{.State.FinishedAt}}";
46
47/// Shell variables the completion watcher fills in and the snippets consume.
48pub mod shell_vars {
49    pub const EXIT: &str = "__start_command_exit";
50    pub const OOM: &str = "__start_command_oom";
51    pub const STARTED: &str = "__start_command_started";
52    pub const FINISHED: &str = "__start_command_finished";
53    pub const ERROR: &str = "__start_command_error";
54    pub const ERROR_TEXT: &str = "__start_command_error_text";
55    pub const SIGNAL: &str = "__start_command_signal";
56    pub const EXIT_TEXT: &str = "__start_command_exit_text";
57    pub const LIFETIME: &str = "__start_command_lifetime";
58    pub const RUNNING: &str = "__start_command_running";
59    /// `true` once the watcher's own `docker rm -f` succeeded (issue #225).
60    pub const REMOVED: &str = "__start_command_removed";
61}
62
63/// `docker inspect -f` template answering "is the container still running?".
64pub const DOCKER_RUNNING_INSPECT_FORMAT: &str = "{{.State.Running}}";
65
66/// Written into the log when `docker logs -f` returned while the container was
67/// still running (issue #174).
68pub const LOG_CAPTURE_STOPPED_NOTE: &str = concat!(
69    "Log capture stopped early: docker logs -f returned while the container ",
70    "was still running (a failed write to this log such as ENOSPC, or a dockerd ",
71    "restart). Waiting for the container to exit."
72);
73
74/// Written into the log when the watcher gave up while the container was still
75/// running. No footer follows: an `Exit Code:` line would be a fabrication.
76pub const STILL_RUNNING_NOTE: &str = concat!(
77    "The watcher stopped observing it before it exited, so it was not removed ",
78    "and the execution record stays executing."
79);
80
81/// Shell condition that holds while the container is running.
82pub fn build_docker_running_condition(quoted_name: &str) -> String {
83    format!(
84        "[ \"$(docker inspect -f '{}' {} 2>/dev/null)\" = true ]",
85        DOCKER_RUNNING_INSPECT_FORMAT, quoted_name
86    )
87}
88
89/// Shell fragment blocking until the container has really exited.
90///
91/// `docker logs -f` and `docker wait` both return early when the *stream* ends
92/// rather than the container: `docker logs -f C >> LOG` returns as soon as its
93/// own write to LOG fails (ENOSPC, when the container filled the disk the log
94/// lives on), and both return when dockerd restarts under live-restore while the
95/// container keeps running. The watcher used to take that return as the
96/// container's exit, inspect a *running* container — Docker reports its zero
97/// values `ExitCode=0 FinishedAt=0001-01-01T00:00:00Z` — and `docker rm -f` the
98/// live workload as a success (issue #174). So the fragment loops on
99/// `.State.Running`, not on the return of the command it waited on; `sleep 1`
100/// keeps a failing `docker wait` from spinning.
101///
102/// `quoted_log_path` (already shell-quoted) records that log capture stopped
103/// early; `None` when there is no log.
104pub fn build_docker_wait_for_exit_snippet(
105    container_name: &str,
106    quoted_log_path: Option<&str>,
107) -> String {
108    let quoted_name = shell_quote(container_name);
109    let running = build_docker_running_condition(&quoted_name);
110    let mut parts = Vec::new();
111    if let Some(log) = quoted_log_path {
112        parts.push(format!(
113            "if {}; then printf '\\n%s\\n' {} >> {} 2>/dev/null; fi",
114            running,
115            shell_quote(LOG_CAPTURE_STOPPED_NOTE),
116            log
117        ));
118    }
119    parts.push(format!(
120        "while {}; do docker wait {} >/dev/null 2>&1 || sleep 1; done",
121        running, quoted_name
122    ));
123    parts.join("; ")
124}
125
126/// Facts read out of a container's `State` after it stopped.
127#[derive(Debug, Clone, Default, PartialEq, Eq)]
128pub struct ContainerPostMortem {
129    pub container_name: String,
130    pub exit_code: Option<i32>,
131    pub oom_killed: Option<bool>,
132    pub started_at: Option<String>,
133    pub finished_at: Option<String>,
134    pub error: Option<String>,
135}
136
137/// Normalize a timestamp reported by `docker inspect`.
138///
139/// Returns `None` for docker's zero time, for the `<no value>` a missing field
140/// renders as, and for anything that does not parse — an honest absence beats a
141/// year-1 timestamp travelling onward as a finish time.
142pub fn normalize_docker_timestamp(value: Option<&str>) -> Option<String> {
143    let text = value.unwrap_or("").trim();
144    if text.is_empty()
145        || text == DOCKER_ZERO_TIME
146        || text == UNKNOWN
147        || text == "<no value>"
148        || text == NO_ERROR
149    {
150        return None;
151    }
152    parse_timestamp(text)?;
153    Some(text.to_string())
154}
155
156fn parse_timestamp(text: &str) -> Option<DateTime<Utc>> {
157    DateTime::parse_from_rfc3339(text)
158        .map(|value| value.with_timezone(&Utc))
159        .ok()
160}
161
162/// Format the time a container was alive, e.g. `5.798s`.
163pub fn format_lifetime(started_at: Option<&str>, finished_at: Option<&str>) -> Option<String> {
164    let start = parse_timestamp(&normalize_docker_timestamp(started_at)?)?;
165    let end = parse_timestamp(&normalize_docker_timestamp(finished_at)?)?;
166    let ms = end.signed_duration_since(start).num_milliseconds();
167    if ms < 0 {
168        return None;
169    }
170    Some(format!("{}.{:03}s", ms / 1000, ms % 1000))
171}
172
173fn optional_bool_text(value: Option<bool>) -> String {
174    match value {
175        Some(value) => value.to_string(),
176        None => UNKNOWN.to_string(),
177    }
178}
179
180/// Render the post-mortem block for facts already held in memory.
181pub fn format_container_post_mortem(facts: &ContainerPostMortem) -> String {
182    let started = normalize_docker_timestamp(facts.started_at.as_deref());
183    let finished = normalize_docker_timestamp(facts.finished_at.as_deref());
184    let lifetime = format_lifetime(facts.started_at.as_deref(), facts.finished_at.as_deref());
185    let error = facts.error.as_deref().unwrap_or("").trim().to_string();
186    let container = if facts.container_name.is_empty() {
187        UNKNOWN
188    } else {
189        &facts.container_name
190    };
191    format!(
192        "{}\nContainer:  {}\nExit Code:  {}\nOOMKilled:  {}\nStartedAt:  {}\nFinishedAt: {}\nLifetime:   {}\nError:      {}\n",
193        POST_MORTEM_HEADER,
194        container,
195        describe_exit_code(facts.exit_code).text,
196        optional_bool_text(facts.oom_killed),
197        started.as_deref().unwrap_or(UNKNOWN),
198        finished.as_deref().unwrap_or(UNKNOWN),
199        lifetime.as_deref().unwrap_or(UNKNOWN),
200        if error.is_empty() { NO_ERROR } else { &error },
201    )
202}
203
204/// Render the single line written when a container is removed, so a successful
205/// run keeps its log terse while still carrying the same facts (issue #171.3).
206pub fn format_container_removal_note(facts: &ContainerPostMortem) -> String {
207    let described = describe_exit_code(facts.exit_code);
208    let signal = described
209        .signal
210        .as_deref()
211        .map(|name| format!(", {}", name))
212        .unwrap_or_default();
213    let lifetime = format_lifetime(facts.started_at.as_deref(), facts.finished_at.as_deref())
214        .unwrap_or_else(|| UNKNOWN.to_string());
215    let container = if facts.container_name.is_empty() {
216        UNKNOWN
217    } else {
218        &facts.container_name
219    };
220    format!(
221        "Container removed: {} (exit {}{}, lifetime {}, oomKilled={})\n",
222        container,
223        described
224            .code
225            .map(|code| code.to_string())
226            .unwrap_or_else(|| UNKNOWN.to_string()),
227        signal,
228        lifetime,
229        optional_bool_text(facts.oom_killed),
230    )
231}
232
233/// Shell fragment reading the container's terminal state.
234///
235/// Also records `.State.Running` in `$__start_command_running`, so the caller
236/// can refuse to remove or finalize a container that is still alive
237/// (issue #174).
238///
239/// The four whitespace-free fields are split with `set --` rather than the
240/// `${var%% *}` / `${var##* }` pair the two-field version used: those only ever
241/// reach the first and the last field. `State.Error` is read separately because
242/// it is free-form text that can contain spaces.
243pub fn build_docker_state_snippet(container_name: &str) -> String {
244    let quoted_name = shell_quote(container_name);
245    [
246        format!(
247            "__start_command_state=$(docker inspect -f '{}' {} 2>/dev/null || printf '%s' '-1 false {} {}')",
248            DOCKER_STATE_INSPECT_FORMAT, quoted_name, UNKNOWN, UNKNOWN
249        ),
250        "set -- $__start_command_state".to_string(),
251        format!("{}=${{1:--1}}", shell_vars::EXIT),
252        format!("{}=${{2:-false}}", shell_vars::OOM),
253        format!("{}=${{3:-{}}}", shell_vars::STARTED, UNKNOWN),
254        format!("{}=${{4:-{}}}", shell_vars::FINISHED, UNKNOWN),
255        format!(
256            "{}=$(docker inspect -f '{{{{.State.Error}}}}' {} 2>/dev/null)",
257            shell_vars::ERROR,
258            quoted_name
259        ),
260        format!(
261            "case \"${}\" in {}|'') {}={};; esac",
262            shell_vars::STARTED,
263            DOCKER_ZERO_TIME,
264            shell_vars::STARTED,
265            UNKNOWN
266        ),
267        format!(
268            "case \"${}\" in {}|'') {}={};; esac",
269            shell_vars::FINISHED,
270            DOCKER_ZERO_TIME,
271            shell_vars::FINISHED,
272            UNKNOWN
273        ),
274        // `ExitCode=0` next to a zero `FinishedAt` is Docker's zero value for a
275        // container that has not finished, never an observed exit 0 (issue #174).
276        format!(
277            "if [ \"${}\" = {} ] && [ \"${}\" = 0 ]; then {}=-1; fi",
278            shell_vars::FINISHED,
279            UNKNOWN,
280            shell_vars::EXIT,
281            shell_vars::EXIT
282        ),
283        format!(
284            "{}=$(docker inspect -f '{}' {} 2>/dev/null)",
285            shell_vars::RUNNING,
286            DOCKER_RUNNING_INSPECT_FORMAT,
287            quoted_name
288        ),
289        build_signal_decode_snippet(),
290        build_lifetime_snippet(),
291    ]
292    .join("; ")
293}
294
295/// Shell fragment decoding `128 + n` into a signal name.
296///
297/// The `case` arms are generated from the very table `describe_exit_code()`
298/// uses, so the log the watcher writes and the `exitReason` `--status` computes
299/// can never name different signals for the same code (issue #171.4).
300pub fn build_signal_decode_snippet() -> String {
301    let arms: Vec<String> = SIGNAL_NAMES
302        .iter()
303        .map(|(signal, name)| format!("{}) {}={};;", 128 + signal, shell_vars::SIGNAL, name))
304        .collect();
305    [
306        format!("{}=''", shell_vars::SIGNAL),
307        format!("case \"${}\" in {} esac", shell_vars::EXIT, arms.join(" ")),
308        format!("{}=\"${}\"", shell_vars::EXIT_TEXT, shell_vars::EXIT),
309        format!(
310            "if [ -n \"${}\" ]; then {}=\"${} (${} - 128+$(({} - 128)))\"; fi",
311            shell_vars::SIGNAL,
312            shell_vars::EXIT_TEXT,
313            shell_vars::EXIT,
314            shell_vars::SIGNAL,
315            shell_vars::EXIT
316        ),
317    ]
318    .join("; ")
319}
320
321/// Shell fragment computing how long the container was alive.
322///
323/// Best effort by design: `date -d` is GNU, `date -j -f` is BSD, and a host that
324/// offers neither leaves the lifetime `unknown` rather than guessing.
325///
326/// BSD `date` cannot parse the fractional seconds docker reports, so the
327/// fallback strips them before parsing and adds them back afterwards.
328/// Truncating both timestamps to whole seconds instead would *not* cancel out: a
329/// container alive from `.942` to `.740` of the next-but-five second measures
330/// 5.798s but truncates to 6.000s, and the error can reach a full second either
331/// way.
332pub fn build_lifetime_snippet() -> String {
333    [
334        concat!(
335            "__start_command_millis() { ",
336            "case \"$1\" in *.*) __start_command_frac=${1#*.};; ",
337            "*) printf '000'; return;; esac; ",
338            "__start_command_frac=${__start_command_frac%%[!0-9]*}; ",
339            "printf '%.3s' \"${__start_command_frac}000\"; }"
340        )
341        .to_string(),
342        concat!(
343            "__start_command_epoch_ms() { ",
344            "__start_command_ts=$(date -u -d \"$1\" +%s%3N 2>/dev/null); ",
345            "case \"$__start_command_ts\" in ''|*[!0-9]*) ",
346            "__start_command_ts=$(date -u -j -f '%Y-%m-%dT%H:%M:%S' \"${1%.*}\" +%s 2>/dev/null) && ",
347            "__start_command_ts=\"${__start_command_ts}$(__start_command_millis \"$1\")\";; esac; ",
348            "case \"$__start_command_ts\" in ''|*[!0-9]*) __start_command_ts='';; esac; ",
349            "printf '%s' \"$__start_command_ts\"; }"
350        )
351        .to_string(),
352        format!("{}={}", shell_vars::LIFETIME, UNKNOWN),
353        format!(
354            "__start_command_t0=$(__start_command_epoch_ms \"${}\")",
355            shell_vars::STARTED
356        ),
357        format!(
358            "__start_command_t1=$(__start_command_epoch_ms \"${}\")",
359            shell_vars::FINISHED
360        ),
361        format!(
362            concat!(
363                "if [ -n \"$__start_command_t0\" ] && [ -n \"$__start_command_t1\" ] && ",
364                "[ \"$__start_command_t1\" -ge \"$__start_command_t0\" ] 2>/dev/null; then ",
365                "__start_command_ms=$((__start_command_t1 - __start_command_t0)); ",
366                "{}=\"$((__start_command_ms / 1000)).$(printf '%03d' \"$((__start_command_ms % 1000))\")s\"; fi"
367            ),
368            shell_vars::LIFETIME
369        ),
370    ]
371    .join("; ")
372}
373
374/// Shell fragment appending the post-mortem block for a kept container.
375pub fn build_docker_post_mortem_snippet(container_name: &str, quoted_log_path: &str) -> String {
376    format!(
377        concat!(
378            "{error_text}=\"${error}\"; ",
379            "if [ -z \"${error_text}\" ]; then {error_text}='{none}'; fi; ",
380            "printf '\\n{header}\\nContainer:  %s\\nExit Code:  %s\\n",
381            "OOMKilled:  %s\\nStartedAt:  %s\\nFinishedAt: %s\\nLifetime:   %s\\nError:      %s\\n' ",
382            "{name} \"${exit_text}\" \"${oom}\" \"${started}\" \"${finished}\" ",
383            "\"${lifetime}\" \"${error_text}\" >> {log}"
384        ),
385        error_text = shell_vars::ERROR_TEXT,
386        error = shell_vars::ERROR,
387        none = NO_ERROR,
388        header = POST_MORTEM_HEADER,
389        name = shell_quote(container_name),
390        exit_text = shell_vars::EXIT_TEXT,
391        oom = shell_vars::OOM,
392        started = shell_vars::STARTED,
393        finished = shell_vars::FINISHED,
394        lifetime = shell_vars::LIFETIME,
395        log = quoted_log_path,
396    )
397}
398
399/// Shell fragment appending the note for a container the watcher lost while it
400/// was still running (issue #174).
401pub fn build_docker_still_running_note_snippet(
402    container_name: &str,
403    quoted_log_path: &str,
404) -> String {
405    let quoted_name = shell_quote(container_name);
406    format!(
407        "printf '\\nContainer still running: %s\\n%s\\nCheck it with: docker inspect %s\\n' {} {} {} >> {}",
408        quoted_name,
409        shell_quote(STILL_RUNNING_NOTE),
410        quoted_name,
411        quoted_log_path
412    )
413}
414
415/// Shell fragment appending the one-line note for a removed container.
416pub fn build_docker_removal_note_snippet(container_name: &str, quoted_log_path: &str) -> String {
417    format!(
418        concat!(
419            "__start_command_signal_note=''; ",
420            "if [ -n \"${signal}\" ]; then __start_command_signal_note=\", ${signal}\"; fi; ",
421            "printf '\\nContainer removed: %s (exit %s%s, lifetime %s, oomKilled=%s)\\n' ",
422            "{name} \"${exit}\" \"$__start_command_signal_note\" \"${lifetime}\" \"${oom}\" >> {log}"
423        ),
424        signal = shell_vars::SIGNAL,
425        name = shell_quote(container_name),
426        exit = shell_vars::EXIT,
427        lifetime = shell_vars::LIFETIME,
428        oom = shell_vars::OOM,
429        log = quoted_log_path,
430    )
431}
start_command/docker_post_mortem.rs

start_command/
docker_post_mortem.rs
