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}
59
60/// Facts read out of a container's `State` after it stopped.
61#[derive(Debug, Clone, Default, PartialEq, Eq)]
62pub struct ContainerPostMortem {
63    pub container_name: String,
64    pub exit_code: Option<i32>,
65    pub oom_killed: Option<bool>,
66    pub started_at: Option<String>,
67    pub finished_at: Option<String>,
68    pub error: Option<String>,
69}
70
71/// Normalize a timestamp reported by `docker inspect`.
72///
73/// Returns `None` for docker's zero time, for the `<no value>` a missing field
74/// renders as, and for anything that does not parse — an honest absence beats a
75/// year-1 timestamp travelling onward as a finish time.
76pub fn normalize_docker_timestamp(value: Option<&str>) -> Option<String> {
77    let text = value.unwrap_or("").trim();
78    if text.is_empty()
79        || text == DOCKER_ZERO_TIME
80        || text == UNKNOWN
81        || text == "<no value>"
82        || text == NO_ERROR
83    {
84        return None;
85    }
86    parse_timestamp(text)?;
87    Some(text.to_string())
88}
89
90fn parse_timestamp(text: &str) -> Option<DateTime<Utc>> {
91    DateTime::parse_from_rfc3339(text)
92        .map(|value| value.with_timezone(&Utc))
93        .ok()
94}
95
96/// Format the time a container was alive, e.g. `5.798s`.
97pub fn format_lifetime(started_at: Option<&str>, finished_at: Option<&str>) -> Option<String> {
98    let start = parse_timestamp(&normalize_docker_timestamp(started_at)?)?;
99    let end = parse_timestamp(&normalize_docker_timestamp(finished_at)?)?;
100    let ms = end.signed_duration_since(start).num_milliseconds();
101    if ms < 0 {
102        return None;
103    }
104    Some(format!("{}.{:03}s", ms / 1000, ms % 1000))
105}
106
107fn optional_bool_text(value: Option<bool>) -> String {
108    match value {
109        Some(value) => value.to_string(),
110        None => UNKNOWN.to_string(),
111    }
112}
113
114/// Render the post-mortem block for facts already held in memory.
115pub fn format_container_post_mortem(facts: &ContainerPostMortem) -> String {
116    let started = normalize_docker_timestamp(facts.started_at.as_deref());
117    let finished = normalize_docker_timestamp(facts.finished_at.as_deref());
118    let lifetime = format_lifetime(facts.started_at.as_deref(), facts.finished_at.as_deref());
119    let error = facts.error.as_deref().unwrap_or("").trim().to_string();
120    let container = if facts.container_name.is_empty() {
121        UNKNOWN
122    } else {
123        &facts.container_name
124    };
125    format!(
126        "{}\nContainer:  {}\nExit Code:  {}\nOOMKilled:  {}\nStartedAt:  {}\nFinishedAt: {}\nLifetime:   {}\nError:      {}\n",
127        POST_MORTEM_HEADER,
128        container,
129        describe_exit_code(facts.exit_code).text,
130        optional_bool_text(facts.oom_killed),
131        started.as_deref().unwrap_or(UNKNOWN),
132        finished.as_deref().unwrap_or(UNKNOWN),
133        lifetime.as_deref().unwrap_or(UNKNOWN),
134        if error.is_empty() { NO_ERROR } else { &error },
135    )
136}
137
138/// Render the single line written when a container is removed, so a successful
139/// run keeps its log terse while still carrying the same facts (issue #171.3).
140pub fn format_container_removal_note(facts: &ContainerPostMortem) -> String {
141    let described = describe_exit_code(facts.exit_code);
142    let signal = described
143        .signal
144        .as_deref()
145        .map(|name| format!(", {}", name))
146        .unwrap_or_default();
147    let lifetime = format_lifetime(facts.started_at.as_deref(), facts.finished_at.as_deref())
148        .unwrap_or_else(|| UNKNOWN.to_string());
149    let container = if facts.container_name.is_empty() {
150        UNKNOWN
151    } else {
152        &facts.container_name
153    };
154    format!(
155        "Container removed: {} (exit {}{}, lifetime {}, oomKilled={})\n",
156        container,
157        described
158            .code
159            .map(|code| code.to_string())
160            .unwrap_or_else(|| UNKNOWN.to_string()),
161        signal,
162        lifetime,
163        optional_bool_text(facts.oom_killed),
164    )
165}
166
167/// Shell fragment reading the container's terminal state.
168///
169/// The four whitespace-free fields are split with `set --` rather than the
170/// `${var%% *}` / `${var##* }` pair the two-field version used: those only ever
171/// reach the first and the last field. `State.Error` is read separately because
172/// it is free-form text that can contain spaces.
173pub fn build_docker_state_snippet(container_name: &str) -> String {
174    let quoted_name = shell_quote(container_name);
175    [
176        format!(
177            "__start_command_state=$(docker inspect -f '{}' {} 2>/dev/null || printf '%s' '-1 false {} {}')",
178            DOCKER_STATE_INSPECT_FORMAT, quoted_name, UNKNOWN, UNKNOWN
179        ),
180        "set -- $__start_command_state".to_string(),
181        format!("{}=${{1:--1}}", shell_vars::EXIT),
182        format!("{}=${{2:-false}}", shell_vars::OOM),
183        format!("{}=${{3:-{}}}", shell_vars::STARTED, UNKNOWN),
184        format!("{}=${{4:-{}}}", shell_vars::FINISHED, UNKNOWN),
185        format!(
186            "{}=$(docker inspect -f '{{{{.State.Error}}}}' {} 2>/dev/null)",
187            shell_vars::ERROR,
188            quoted_name
189        ),
190        format!(
191            "case \"${}\" in {}|'') {}={};; esac",
192            shell_vars::STARTED,
193            DOCKER_ZERO_TIME,
194            shell_vars::STARTED,
195            UNKNOWN
196        ),
197        format!(
198            "case \"${}\" in {}|'') {}={};; esac",
199            shell_vars::FINISHED,
200            DOCKER_ZERO_TIME,
201            shell_vars::FINISHED,
202            UNKNOWN
203        ),
204        build_signal_decode_snippet(),
205        build_lifetime_snippet(),
206    ]
207    .join("; ")
208}
209
210/// Shell fragment decoding `128 + n` into a signal name.
211///
212/// The `case` arms are generated from the very table `describe_exit_code()`
213/// uses, so the log the watcher writes and the `exitReason` `--status` computes
214/// can never name different signals for the same code (issue #171.4).
215pub fn build_signal_decode_snippet() -> String {
216    let arms: Vec<String> = SIGNAL_NAMES
217        .iter()
218        .map(|(signal, name)| format!("{}) {}={};;", 128 + signal, shell_vars::SIGNAL, name))
219        .collect();
220    [
221        format!("{}=''", shell_vars::SIGNAL),
222        format!("case \"${}\" in {} esac", shell_vars::EXIT, arms.join(" ")),
223        format!("{}=\"${}\"", shell_vars::EXIT_TEXT, shell_vars::EXIT),
224        format!(
225            "if [ -n \"${}\" ]; then {}=\"${} (${} - 128+$(({} - 128)))\"; fi",
226            shell_vars::SIGNAL,
227            shell_vars::EXIT_TEXT,
228            shell_vars::EXIT,
229            shell_vars::SIGNAL,
230            shell_vars::EXIT
231        ),
232    ]
233    .join("; ")
234}
235
236/// Shell fragment computing how long the container was alive.
237///
238/// Best effort by design: `date -d` is GNU, `date -j -f` is BSD, and a host that
239/// offers neither leaves the lifetime `unknown` rather than guessing.
240///
241/// BSD `date` cannot parse the fractional seconds docker reports, so the
242/// fallback strips them before parsing and adds them back afterwards.
243/// Truncating both timestamps to whole seconds instead would *not* cancel out: a
244/// container alive from `.942` to `.740` of the next-but-five second measures
245/// 5.798s but truncates to 6.000s, and the error can reach a full second either
246/// way.
247pub fn build_lifetime_snippet() -> String {
248    [
249        concat!(
250            "__start_command_millis() { ",
251            "case \"$1\" in *.*) __start_command_frac=${1#*.};; ",
252            "*) printf '000'; return;; esac; ",
253            "__start_command_frac=${__start_command_frac%%[!0-9]*}; ",
254            "printf '%.3s' \"${__start_command_frac}000\"; }"
255        )
256        .to_string(),
257        concat!(
258            "__start_command_epoch_ms() { ",
259            "__start_command_ts=$(date -u -d \"$1\" +%s%3N 2>/dev/null); ",
260            "case \"$__start_command_ts\" in ''|*[!0-9]*) ",
261            "__start_command_ts=$(date -u -j -f '%Y-%m-%dT%H:%M:%S' \"${1%.*}\" +%s 2>/dev/null) && ",
262            "__start_command_ts=\"${__start_command_ts}$(__start_command_millis \"$1\")\";; esac; ",
263            "case \"$__start_command_ts\" in ''|*[!0-9]*) __start_command_ts='';; esac; ",
264            "printf '%s' \"$__start_command_ts\"; }"
265        )
266        .to_string(),
267        format!("{}={}", shell_vars::LIFETIME, UNKNOWN),
268        format!(
269            "__start_command_t0=$(__start_command_epoch_ms \"${}\")",
270            shell_vars::STARTED
271        ),
272        format!(
273            "__start_command_t1=$(__start_command_epoch_ms \"${}\")",
274            shell_vars::FINISHED
275        ),
276        format!(
277            concat!(
278                "if [ -n \"$__start_command_t0\" ] && [ -n \"$__start_command_t1\" ] && ",
279                "[ \"$__start_command_t1\" -ge \"$__start_command_t0\" ] 2>/dev/null; then ",
280                "__start_command_ms=$((__start_command_t1 - __start_command_t0)); ",
281                "{}=\"$((__start_command_ms / 1000)).$(printf '%03d' \"$((__start_command_ms % 1000))\")s\"; fi"
282            ),
283            shell_vars::LIFETIME
284        ),
285    ]
286    .join("; ")
287}
288
289/// Shell fragment appending the post-mortem block for a kept container.
290pub fn build_docker_post_mortem_snippet(container_name: &str, quoted_log_path: &str) -> String {
291    format!(
292        concat!(
293            "{error_text}=\"${error}\"; ",
294            "if [ -z \"${error_text}\" ]; then {error_text}='{none}'; fi; ",
295            "printf '\\n{header}\\nContainer:  %s\\nExit Code:  %s\\n",
296            "OOMKilled:  %s\\nStartedAt:  %s\\nFinishedAt: %s\\nLifetime:   %s\\nError:      %s\\n' ",
297            "{name} \"${exit_text}\" \"${oom}\" \"${started}\" \"${finished}\" ",
298            "\"${lifetime}\" \"${error_text}\" >> {log}"
299        ),
300        error_text = shell_vars::ERROR_TEXT,
301        error = shell_vars::ERROR,
302        none = NO_ERROR,
303        header = POST_MORTEM_HEADER,
304        name = shell_quote(container_name),
305        exit_text = shell_vars::EXIT_TEXT,
306        oom = shell_vars::OOM,
307        started = shell_vars::STARTED,
308        finished = shell_vars::FINISHED,
309        lifetime = shell_vars::LIFETIME,
310        log = quoted_log_path,
311    )
312}
313
314/// Shell fragment appending the one-line note for a removed container.
315pub fn build_docker_removal_note_snippet(container_name: &str, quoted_log_path: &str) -> String {
316    format!(
317        concat!(
318            "__start_command_signal_note=''; ",
319            "if [ -n \"${signal}\" ]; then __start_command_signal_note=\", ${signal}\"; fi; ",
320            "printf '\\nContainer removed: %s (exit %s%s, lifetime %s, oomKilled=%s)\\n' ",
321            "{name} \"${exit}\" \"$__start_command_signal_note\" \"${lifetime}\" \"${oom}\" >> {log}"
322        ),
323        signal = shell_vars::SIGNAL,
324        name = shell_quote(container_name),
325        exit = shell_vars::EXIT,
326        lifetime = shell_vars::LIFETIME,
327        oom = shell_vars::OOM,
328        log = quoted_log_path,
329    )
330}
start_command/docker_post_mortem.rs

start_command/
docker_post_mortem.rs
