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

start_command/
docker_post_mortem.rs
