isb_core/stack/
failure.rs

1//! Why a replica did not come up.
2//!
3//! A replica that fails its rollout is deleted at once and the controller
4//! tries again, so by the time anyone asks for its logs the instance is
5//! gone (or dying, and incus answers the console request with an error).
6//! The controller therefore reads the failed instance's output before it
7//! deletes it, puts the last lines in the failure message (the deployment
8//! log, the service's status) and keeps them here for `app_logs`, which
9//! shows them beside the live replicas' logs.
10
11use std::collections::BTreeMap;
12use std::sync::Mutex;
13use std::time::Duration;
14
15use serde::Serialize;
16
17use super::controller::{Inst, list_instances};
18use crate::client::Client;
19use crate::error::{Error, Result};
20use crate::sandbox::Sandbox;
21use crate::supervise;
22
23/// How many lines of a failed replica's output are read.
24const READ_LINES: usize = 60;
25/// How many of them go into the failure message.
26const MESSAGE_LINES: usize = 8;
27/// The most characters the message takes from them.
28const MESSAGE_CHARS: usize = 1200;
29
30/// The first wait after a replica failed because its image is missing.
31pub const IMAGE_RETRY: Duration = Duration::from_secs(300);
32/// The longest wait between such attempts.
33pub const IMAGE_RETRY_MAX: Duration = Duration::from_secs(3600);
34
35/// Why a replica's image could not be pulled, in plain words, when that is
36/// why it failed: `image docker:x:1 not found (manifest unknown)`. `None`
37/// for any other failure, and for a registry that did not answer (that
38/// may pass by itself).
39pub fn image_missing(image: &str, err: &str) -> Option<String> {
40    if !err.contains("Failed getting remote image") && !err.contains("Error parsing image name") {
41        return None;
42    }
43    match crate::image_check::classify(err) {
44        crate::image_check::Probe::NotFound(why) => {
45            Some(format!("image {image} not found ({why})"))
46        }
47        crate::image_check::Probe::Denied(why) => Some(format!(
48            "image {image} cannot be pulled without credentials ({why}): it is private or does not exist"
49        )),
50        _ => None,
51    }
52}
53
54/// After a replica could not be created: how long to wait before the next
55/// attempt (`prev` was the last wait), and the service's message. An image
56/// its registry does not have will not appear by itself (until someone
57/// pushes it), so that waits longest, and is said plainly instead of in
58/// incus' words.
59pub fn retry(prev: Option<Duration>, image: &str, msg: &str, e: &Error) -> (Duration, String) {
60    let missing = image_missing(image, &e.to_string());
61    let (first, cap) = match missing {
62        Some(_) => (IMAGE_RETRY, IMAGE_RETRY_MAX),
63        None => (Duration::from_secs(10), Duration::from_secs(300)),
64    };
65    let wait = prev.map(|w| (w * 2).clamp(first, cap)).unwrap_or(first);
66    let message = match missing {
67        Some(m) => format!(
68            "{m}: change the image and deploy again (retrying in {}m)",
69            wait.as_secs() / 60
70        ),
71        None => format!("{msg}; retrying in {wait:?}"),
72    };
73    (wait, message)
74}
75
76/// The output of the last replica of a service that failed to come up.
77#[derive(Debug, Clone, PartialEq, Eq, Serialize)]
78pub struct FailedAttempt {
79    /// The instance that was deleted.
80    pub instance: String,
81    /// When it failed, in milliseconds since the epoch.
82    pub at_ms: u64,
83    /// Why (the failure message without the output).
84    pub reason: String,
85    /// The last lines it printed.
86    pub output: String,
87}
88
89/// The last failed attempt of each (stack, service).
90#[derive(Default)]
91pub struct Failures(Mutex<BTreeMap<(String, String), FailedAttempt>>);
92
93impl Failures {
94    pub fn record(&self, stack: &str, service: &str, a: FailedAttempt) {
95        self.0
96            .lock()
97            .unwrap_or_else(|e| e.into_inner())
98            .insert((stack.to_string(), service.to_string()), a);
99    }
100
101    pub fn last(&self, stack: &str, service: &str) -> Option<FailedAttempt> {
102        self.0
103            .lock()
104            .unwrap_or_else(|e| e.into_inner())
105            .get(&(stack.to_string(), service.to_string()))
106            .cloned()
107    }
108
109    /// A service that came up again has nothing to explain.
110    pub fn clear(&self, stack: &str, service: &str) {
111        self.0
112            .lock()
113            .unwrap_or_else(|e| e.into_inner())
114            .remove(&(stack.to_string(), service.to_string()));
115    }
116}
117
118/// The last `n` non-empty lines of `text`, joined with ` | ` and cut to
119/// `max` characters (from the front: the end is what explains it).
120pub fn one_line(text: &str, n: usize, max: usize) -> String {
121    let lines: Vec<&str> = text
122        .lines()
123        .map(str::trim_end)
124        .filter(|l| !l.trim().is_empty())
125        .collect();
126    let joined = lines[lines.len().saturating_sub(n)..].join(" | ");
127    let count = joined.chars().count();
128    if count <= max {
129        return joined;
130    }
131    let tail: String = joined.chars().skip(count - max).collect();
132    format!("...{tail}")
133}
134
135/// How long a failed instance's output is waited for. incus gives the
136/// console of a container that has just exited only after a moment: an
137/// early read is an error or empty.
138const OUTPUT_WAIT: Duration = if cfg!(test) {
139    Duration::from_millis(100)
140} else {
141    Duration::from_secs(8)
142};
143
144/// Poll `read` until it yields text, for at most `within`. An empty string
145/// when the instance printed nothing or cannot be read: the failure is
146/// explained without it.
147fn poll_output(
148    read: &mut dyn FnMut() -> Result<String>,
149    within: Duration,
150    poll: Duration,
151) -> String {
152    let until = std::time::Instant::now() + within;
153    loop {
154        if let Ok(t) = read() {
155            if !t.trim().is_empty() {
156                return t;
157            }
158        }
159        if std::time::Instant::now() >= until {
160            return String::new();
161        }
162        std::thread::sleep(poll);
163    }
164}
165
166/// The failed instance's output, read before it is deleted.
167fn read_output(client: &Client, name: &str, service: &str, oci: bool) -> String {
168    poll_output(
169        &mut || {
170            let sb = Sandbox::get(client, name)?;
171            supervise::logs(&sb, service, oci, READ_LINES)
172        },
173        OUTPUT_WAIT,
174        Duration::from_millis(500),
175    )
176}
177
178/// The failure of replica `name` with its last output in the message, and
179/// the attempt to keep. Called before the instance is deleted.
180pub fn explain(
181    client: &Client,
182    name: &str,
183    service: &str,
184    oci: bool,
185    e: Error,
186    now_ms: u64,
187) -> (Error, FailedAttempt) {
188    let output = read_output(client, name, service, oci);
189    let reason = e.to_string();
190    let tail = one_line(&output, MESSAGE_LINES, MESSAGE_CHARS);
191    let err = if tail.is_empty() {
192        e
193    } else {
194        Error::invalid(format!("{reason}; its last output: {tail}"))
195    };
196    let attempt = FailedAttempt {
197        instance: name.to_string(),
198        at_ms: now_ms,
199        reason,
200        output,
201    };
202    (err, attempt)
203}
204
205/// Recent output of a service's replicas (or one slot's), by instance. A
206/// replica that is being replaced as this is asked, or whose output cannot
207/// be read, shows why in place of its text instead of failing the call.
208pub fn replica_logs(
209    client: &Client,
210    stack: &str,
211    service: &str,
212    oci: bool,
213    slot: Option<u32>,
214    lines: usize,
215) -> Result<BTreeMap<String, String>> {
216    let mut out = BTreeMap::new();
217    for i in list_instances(client, stack, Some(service))? {
218        if slot.is_some_and(|s| s != i.slot) {
219            continue;
220        }
221        out.insert(i.name.clone(), one_replica(client, &i, service, oci, lines));
222    }
223    Ok(out)
224}
225
226fn one_replica(client: &Client, i: &Inst, service: &str, oci: bool, lines: usize) -> String {
227    let mut last = String::new();
228    for attempt in 0..2 {
229        match Sandbox::get(client, &i.name).and_then(|sb| supervise::logs(&sb, service, oci, lines))
230        {
231            Ok(t) => return t,
232            Err(e) if e.is_not_found() => return "(replaced while reading its logs)".into(),
233            Err(e) => last = e.to_string(),
234        }
235        if attempt == 0 {
236            std::thread::sleep(Duration::from_millis(300));
237        }
238    }
239    format!("(no logs: {last})")
240}
241
242#[cfg(test)]
243mod tests {
244    use super::*;
245
246    #[test]
247    fn a_missing_image_backs_off_long_and_says_so() {
248        let e = Error::invalid(
249            "create instance x failed: Failed getting remote image info: Failed to run: skopeo inspect docker://docker.io/library/traefik:whoami: reading manifest whoami in docker.io/library/traefik: manifest unknown",
250        );
251        let (wait, m) = retry(None, "docker:traefik:whoami", "slot 1: ...", &e);
252        assert_eq!(wait, Duration::from_secs(300));
253        assert_eq!(
254            m,
255            "image docker:traefik:whoami not found (manifest unknown): change the image and deploy again (retrying in 5m)"
256        );
257        let mut w = Some(Duration::from_secs(10));
258        for _ in 0..8 {
259            w = Some(retry(w, "docker:traefik:whoami", "slot 1: ...", &e).0);
260        }
261        assert_eq!(w, Some(Duration::from_secs(3600)));
262        // Anything else starts at seconds.
263        let (wait, m) = retry(
264            None,
265            "docker:nginx",
266            "slot 1: boom",
267            &Error::invalid("boom"),
268        );
269        assert_eq!(wait, Duration::from_secs(10));
270        assert_eq!(m, "slot 1: boom; retrying in 10s");
271    }
272
273    #[test]
274    fn a_pull_of_a_missing_image_is_said_plainly() {
275        let incus = r#"create instance web-1 failed: Failed getting remote image info: Failed to run: skopeo --insecure-policy inspect docker://docker.io/library/traefik:whoami --no-tags: exit status 2 (time="2026-10-05T04:38:08Z" level=fatal msg="Error parsing image name \"docker://docker.io/library/traefik:whoami\": reading manifest whoami in docker.io/library/traefik: manifest unknown")"#;
276        assert_eq!(
277            image_missing("docker:traefik:whoami", incus).as_deref(),
278            Some("image docker:traefik:whoami not found (manifest unknown)")
279        );
280        let offline = "create instance web-1 failed: Failed getting remote image info: Failed to run: skopeo: dial tcp: lookup registry-1.docker.io: no such host";
281        assert_eq!(image_missing("docker:nginx", offline), None);
282        assert_eq!(
283            image_missing("docker:nginx", "out of disk: manifest unknown"),
284            None
285        );
286    }
287
288    #[test]
289    fn the_message_carries_the_end_of_the_output() {
290        let out = "starting\n\nconnecting to db\nError: getaddrinfo ENOTFOUND umami-db\n   at GetAddrInfoReqWrap\n";
291        assert_eq!(
292            one_line(out, 2, 500),
293            "Error: getaddrinfo ENOTFOUND umami-db |    at GetAddrInfoReqWrap"
294        );
295        assert_eq!(one_line("", 8, 100), "");
296        assert_eq!(one_line("a\nb\nc\n", 8, 100), "a | b | c");
297        // Cut from the front, keeping the last characters.
298        let long = format!("{}\nENOTFOUND", "x".repeat(300));
299        let s = one_line(&long, 8, 40);
300        assert!(s.starts_with("...") && s.ends_with("ENOTFOUND"), "{s}");
301        assert_eq!(s.chars().count(), 43);
302    }
303
304    #[test]
305    fn the_last_attempt_is_kept_per_service_until_it_serves_again() {
306        let f = Failures::default();
307        let a = FailedAttempt {
308            instance: "shop-web-1-abc".into(),
309            at_ms: 7,
310            reason: "failed within the 5s monitor period".into(),
311            output: "boom".into(),
312        };
313        assert_eq!(f.last("shop", "web"), None);
314        f.record("shop", "web", a.clone());
315        assert_eq!(f.last("shop", "web"), Some(a));
316        assert_eq!(f.last("shop", "db"), None);
317        f.clear("shop", "web");
318        assert_eq!(f.last("shop", "web"), None);
319    }
320
321    #[test]
322    fn an_unreadable_instance_still_explains_the_failure_without_output() {
323        // No incusd behind this socket: reading the output fails, and the
324        // original failure is returned unchanged.
325        let c = Client::with_socket("/nonexistent/incus.sock");
326        let (e, a) = explain(
327            &c,
328            "gone",
329            "web",
330            true,
331            Error::invalid("failed within the 5s monitor period"),
332            9,
333        );
334        assert_eq!(e.to_string(), "failed within the 5s monitor period");
335        assert_eq!(a.reason, "failed within the 5s monitor period");
336        assert!(a.output.is_empty());
337        assert_eq!((a.instance.as_str(), a.at_ms), ("gone", 9));
338    }
339
340    #[test]
341    fn a_replica_deleted_while_its_logs_are_read_does_not_fail_the_call() {
342        use crate::client::fake::{Route, serve};
343        use crate::stack::{LABEL_SERVICE, LABEL_SLOT, LABEL_STACK};
344        // The instance is listed, then gone (the crash loop replaced it).
345        let (_d, c) = serve(vec![Route {
346            prefix: "GET /1.0/instances?recursion=1",
347            status: 200,
348            body: serde_json::json!([{
349                "name": "web-1-aaaa",
350                "status": "Running",
351                "config": {
352                    format!("user.{LABEL_STACK}"): "shop",
353                    format!("user.{LABEL_SERVICE}"): "web",
354                    format!("user.{LABEL_SLOT}"): "1",
355                },
356            }]),
357        }]);
358        let logs = replica_logs(&c, "shop", "web", true, None, 50).unwrap();
359        assert_eq!(logs.len(), 1);
360        assert_eq!(logs["web-1-aaaa"], "(replaced while reading its logs)");
361        // Another slot's logs were asked for: nothing is read.
362        assert!(
363            replica_logs(&c, "shop", "web", true, Some(2), 50)
364                .unwrap()
365                .is_empty()
366        );
367    }
368
369    #[test]
370    fn output_that_arrives_late_is_waited_for_and_silence_ends() {
371        let mut n = 0;
372        let got = poll_output(
373            &mut || {
374                n += 1;
375                match n {
376                    1 => Err(Error::invalid("connection refused")),
377                    2 => Ok("\n".into()),
378                    _ => Ok("Error: getaddrinfo ENOTFOUND db\n".into()),
379                }
380            },
381            Duration::from_secs(5),
382            Duration::from_millis(1),
383        );
384        assert_eq!(got, "Error: getaddrinfo ENOTFOUND db\n");
385        assert_eq!(n, 3);
386        // An instance that prints nothing is not waited on for long.
387        let t = std::time::Instant::now();
388        let none = poll_output(
389            &mut || Ok(String::new()),
390            Duration::from_millis(30),
391            Duration::from_millis(10),
392        );
393        assert_eq!(none, "");
394        assert!(t.elapsed() < Duration::from_secs(2));
395    }
396}
isb_core/stack/failure.rs

isb_core/stack/
failure.rs
