jevsnes.git / packages / zbanks / src / recovery.rs
1//! Recovering from a stall the bot's own retry mechanism cannot reach.
2//!
3//! `Bot::retry_all_given_up` (called by `watch_given_up` on every tick) already
4//! puts a goal the bot gave up on back on the list - but only when Link's
5//! possessions change, which is the right trigger for "a goal that needed a
6//! new key" and the wrong one for a goal that keeps failing for a reason no
7//! possession change will ever touch. Measured (research/zbanks-alttp.md,
8//! the door `D 0x80` stall in dungeon room `$0123`): the SAME `GOTO_POINT`
9//! failed five times, about 127 frames apart, until the planner had nothing
10//! left to score and gave up - Link was standing still the whole time, so
11//! `watch_given_up` never had a possession change to fire on, and the bot
12//! never tried again.
13//!
14//! [`Recovery`] is the same retry - [`crate::Bot::retry_all_given_up`],
15//! unconditional on a possession change - triggered whenever the CALLER says
16//! the bot is stalled (`crate::stall::Detector` in the window, or bare
17//! `manual_mode` headless), bounded so it cannot spin forever on a goal that
18//! is failing for a real, unfixable reason: escalating backoff between
19//! attempts, and a cap of attempts that make no progress (a new item, key,
20//! or completed goal) before it gives up for good and says so loudly. It
21//! lives here, not in `apps/native`, so `apps/zbanks` (headless) gets the
22//! exact same mechanics rather than a second, divergent implementation.
23
24use alttp::Place;
25use console::Console;
26
27use crate::{Bot, possessions};
28
29/// How many recoveries with no progress before giving up for good, for the
30/// life of this [`Recovery`] (a fresh one, like a fresh [`Bot`], only comes
31/// from a restart - the same one-way-latch shape as `stall::Detector`'s own
32/// per-process reset).
33pub const CAP: u32 = 5;
34
35/// Frames to wait before each numbered attempt: the Nth attempt (1-based)
36/// waits `BACKOFF[N-1]`, and the schedule holds at its last entry after
37/// that. Doubling from about ten seconds (`600 / 60.0988`) up to roughly
38/// `stall::STALL_FRAMES` (five minutes), so a goal that fails fast is
39/// retried fast and one that keeps failing is not hammered every frame.
40pub const BACKOFF: [u32; 5] = [600, 1_200, 2_400, 4_800, 9_600];
41
42/// One attempted recovery, for the log, the panel and the `bot` MCP tool.
43#[derive(Clone, Copy, Debug, PartialEq, Eq)]
44pub struct Event {
45    /// The frame the attempt was made on.
46    pub frame: u32,
47    /// 1-based: which numbered attempt since the last progress (or since the
48    /// stall started, if there has been none).
49    pub attempt: u32,
50    /// How many goals `retry_all_given_up` actually put back on this try.
51    pub restored: usize,
52    /// This attempt reached [`CAP`]: recovery will not try again.
53    pub gave_up: bool,
54}
55
56/// The pure backoff/cap decision - frame, whether the caller currently
57/// considers the bot stalled, and whether the bot has made progress since
58/// the last attempt - kept apart from [`Recovery`] so it can be tested
59/// without a real bot, console or C.
60///
61/// Only [`progressed`](Self::poll)`==true` forgets the count - NOT a bare
62/// `stalled==false` reading. The earlier design reset on `!stalled` alone,
63/// on the theory that a stall clearing at all was evidence something was
64/// fixed; it is not, when the very thing that cleared it is
65/// `retry_all_given_up` mechanically adding a goal back (which clears
66/// `ap_manual_mode` as a side effect, `crate::Bot::watch_given_up`'s
67/// `zb_goal_add`) regardless of whether that goal can actually succeed.
68/// Measured live (`research/zbanks-alttp.md`, "Recovery's cap never
69/// engaged" and "The door D 0x80 stall"): a recovered goal that cannot
70/// succeed fails again a few hundred to ~16,500 frames later, `stalled`
71/// toggles back to `true`, and under the old rule every such cycle started
72/// a "fresh" stall at attempt 1 - forever, because the toggle itself was
73/// read as proof of a fix. Held across the toggle instead, the count
74/// escalates and reaches [`CAP`] on a stall that keeps recurring for the
75/// same unfixed reason, exactly as intended.
76#[derive(Default)]
77struct Schedule {
78    attempts: u32,
79    next_at: Option<u32>,
80    gave_up: bool,
81}
82
83impl Schedule {
84    /// `Some(n)` exactly when attempt `n` should be made now.
85    fn poll(&mut self, frame: u32, stalled: bool, progressed: bool) -> Option<u32> {
86        if self.gave_up {
87            return None;
88        }
89        if progressed {
90            // Something the bot did not have before now shows up - a retry
91            // paid off, or unrelated real advancement happened. Forget the
92            // count and any pending backoff, whether or not the caller
93            // currently reports a stall: a genuinely fresh situation should
94            // not carry a failing goal's baggage into it.
95            self.attempts = 0;
96            self.next_at = None;
97        }
98        if !stalled {
99            // Nothing to attempt right now, but - unlike a genuine
100            // `progressed` reading - a bare "not stalled" is not trusted to
101            // mean the underlying problem is gone (see the type doc): the
102            // count and backoff are PRESERVED so a recurrence of the same
103            // stall resumes escalating rather than restarting at 1.
104            return None;
105        }
106        if self.next_at.is_some_and(|at| frame < at) {
107            return None;
108        }
109        self.attempts += 1;
110        let backoff = BACKOFF[(self.attempts as usize - 1).min(BACKOFF.len() - 1)];
111        self.next_at = Some(frame + backoff);
112        if self.attempts >= CAP {
113            self.gave_up = true;
114        }
115        Some(self.attempts)
116    }
117}
118
119/// What the panel and the `bot` tool show: the last attempt, if any, and
120/// whether recovery has given up for good.
121#[derive(Clone, Copy, Debug)]
122pub struct Status {
123    pub last: Option<Event>,
124    pub gave_up: bool,
125}
126
127/// One reading of everything [`Recovery`] judges progress from.
128type Reading = (Vec<u8>, u64, (Place, u16, u16));
129
130/// The pure half of what counts as progress - kept apart from [`Recovery`]
131/// so it can be tested without a real [`Bot`]/[`Console`]. See the doc on
132/// [`Recovery`] itself for why a completed goal alone is not trusted.
133fn progressed(before: &Reading, now: &Reading) -> bool {
134    let (before_poss, before_completed, before_pos) = before;
135    let (now_poss, now_completed, now_pos) = now;
136    before_poss != now_poss || (before_completed != now_completed && before_pos != now_pos)
137}
138
139/// Drives [`Schedule`] against a real [`Bot`]: what counts as progress and
140/// the actual retry call.
141///
142/// Progress is [`possessions`] changing (Link cannot gain an item, key,
143/// pendant or crystal without being at its location, so this alone is
144/// trustworthy) OR the bot's own completed-goal count changing TOGETHER WITH
145/// Link's own position having moved since the last check. A completed goal
146/// on its own is not trustworthy: `retry_all_given_up` re-adds every
147/// given-up goal from scratch (attempts reset to 0), and one whose target
148/// the save already satisfies - a chest already opened, a door already
149/// unlocked - can leave the bot's goal list "complete" on its very first
150/// re-evaluation, before Link takes a single step. Measured live
151/// (`research/zbanks-alttp.md`, the door `D 0x80` stall in room `$0123`):
152/// three real recoveries (frames 16567, 33125, 49683, then 66241, 82799,
153/// 99357, 115915 - exactly 16558 frames apart, every time, a deterministic
154/// replay of the same 33 restored goals) each logged `"attempt":1`, never
155/// escalating, because the completed-goal count alone kept resetting the
156/// counter although Link's own position never changed once across any of
157/// them. Gating a completed goal on a position change closes exactly that
158/// hole without discarding the signal entirely: a goal that completes
159/// because Link genuinely reached somewhere new still counts. This alone,
160/// however, is not what made the live incident loop forever - see
161/// [`Schedule`]'s own doc comment for the larger half of the fix.
162#[derive(Default)]
163pub struct Recovery {
164    schedule: Schedule,
165    baseline: Option<Reading>,
166    last: Option<Event>,
167}
168
169impl Recovery {
170    pub fn new() -> Self {
171        Self::default()
172    }
173
174    /// Call once a frame with whatever the caller currently considers a
175    /// stall, and Link's current position (the same reading the caller
176    /// already took for its own `stall::Signal`, so this crate does not
177    /// duplicate the WRAM-position read). Cheap when nothing is due - a byte
178    /// comparison and a frame check - and only calls into the C
179    /// (`Bot::retry_all_given_up`) when an attempt is actually made.
180    pub fn consider(
181        &mut self,
182        bot: &mut Bot,
183        console: &Console,
184        stalled: bool,
185        frame: u32,
186        position: (Place, u16, u16),
187    ) -> Option<Event> {
188        let now: Reading = (possessions(console.wram()), bot.completed_count(), position);
189        let is_progress = self.baseline.as_ref().is_some_and(|before| progressed(before, &now));
190        self.baseline = Some(now);
191        let attempt = self.schedule.poll(frame, stalled, is_progress)?;
192        let restored = bot.retry_all_given_up(&format!("stall recovery, attempt {attempt} of {CAP}"));
193        let event = Event { frame, attempt, restored, gave_up: self.schedule.gave_up };
194        self.last = Some(event);
195        Some(event)
196    }
197
198    pub fn status(&self) -> Status {
199        Status { last: self.last, gave_up: self.schedule.gave_up }
200    }
201}
202
203#[cfg(test)]
204mod tests {
205    use super::*;
206
207    #[test]
208    fn quiet_while_not_stalled() {
209        let mut s = Schedule::default();
210        for frame in 0..100_000 {
211            assert_eq!(s.poll(frame, false, false), None, "frame {frame}");
212        }
213    }
214
215    #[test]
216    fn first_attempt_is_immediate() {
217        let mut s = Schedule::default();
218        assert_eq!(s.poll(1000, true, false), Some(1));
219    }
220
221    #[test]
222    fn backoff_escalates_between_attempts() {
223        let mut s = Schedule::default();
224        assert_eq!(s.poll(0, true, false), Some(1));
225        // Too soon: BACKOFF[0] = 600 frames have not passed since attempt 1.
226        assert_eq!(s.poll(599, true, false), None);
227        assert_eq!(s.poll(600, true, false), Some(2));
228        // Attempt 3 waits BACKOFF[1] = 1200 frames from attempt 2 (frame 600).
229        assert_eq!(s.poll(600 + 1199, true, false), None);
230        assert_eq!(s.poll(600 + 1200, true, false), Some(3));
231    }
232
233    #[test]
234    fn backoff_holds_at_its_last_entry_past_the_schedule() {
235        let mut s = Schedule::default();
236        let mut frame = 0u32;
237        for expected in 1..=BACKOFF.len() as u32 {
238            assert_eq!(s.poll(frame, true, false), Some(expected));
239            frame += BACKOFF[expected as usize - 1];
240        }
241        // One more attempt would reach CAP (== BACKOFF.len() + 1 here); stop
242        // one short so this test is only about the backoff holding, not the
243        // cap - waiting less than the last entry must still refuse.
244        assert_eq!(s.poll(frame + BACKOFF[BACKOFF.len() - 1] - 1, true, false), None);
245    }
246
247    #[test]
248    fn progress_resets_the_count_and_the_backoff() {
249        let mut s = Schedule::default();
250        assert_eq!(s.poll(0, true, false), Some(1));
251        // Far too soon for attempt 2 on the ordinary schedule (needs 600
252        // frames) - but progress arrived, which resets the schedule exactly
253        // as if it were new: the next poll is a fresh "attempt 1".
254        assert_eq!(s.poll(100, true, true), Some(1));
255        assert_eq!(s.poll(100 + 599, true, false), None);
256        assert_eq!(s.poll(100 + 600, true, false), Some(2));
257    }
258
259    #[test]
260    fn gives_up_after_the_cap_and_never_tries_again() {
261        let mut s = Schedule::default();
262        let mut frame = 0u32;
263        let mut last = None;
264        for _ in 0..CAP {
265            // The largest backoff entry is always long enough to clear
266            // whichever attempt's wait is actually in force.
267            frame += BACKOFF[BACKOFF.len() - 1] + 1;
268            last = s.poll(frame, true, false);
269        }
270        assert_eq!(last, Some(CAP));
271        assert!(s.gave_up);
272        // Even with progress and all the time in the world, nothing more
273        // happens: giving up is for good, not just for this backoff.
274        frame += 1_000_000;
275        assert_eq!(s.poll(frame, true, true), None);
276    }
277
278    #[test]
279    fn a_stall_that_clears_with_real_progress_forgets_the_count() {
280        let mut s = Schedule::default();
281        for _ in 0..CAP - 1 {
282            let frame = s.next_at.unwrap_or(0);
283            s.poll(frame, true, false);
284        }
285        assert!(!s.gave_up);
286        // The stall clears, WITH progress (something genuinely changed) -
287        // the next stall starts counting from attempt 1 again, not from
288        // where the last one left off.
289        assert_eq!(s.poll(1_000_000, false, true), None);
290        assert_eq!(s.poll(1_000_000, true, false), Some(1));
291    }
292
293    #[test]
294    fn a_stall_that_clears_with_no_progress_keeps_escalating_on_recurrence() {
295        // The live incident this fix is for: a goal recovery revives clears
296        // `ap_manual_mode` as a side effect (`stalled` reads false for a
297        // tick or many), then fails again with nothing having actually
298        // changed, and `stalled` reads true again. A bare clear must NOT
299        // erase the count, or every recurrence of the same unfixed stall
300        // reads as attempt 1 forever - see the type's own doc comment.
301        let mut s = Schedule::default();
302        assert_eq!(s.poll(0, true, false), Some(1));
303        // The recovery "worked" for a moment: manual_mode cleared.
304        assert_eq!(s.poll(1, false, false), None);
305        // ...and failed again shortly after, with nothing having changed.
306        assert_eq!(s.poll(600, true, false), Some(2));
307        assert_eq!(s.poll(601, false, false), None);
308        assert_eq!(s.poll(600 + 1200, true, false), Some(3));
309    }
310
311    #[test]
312    fn the_live_sequence_with_the_stall_toggling_off_between_recoveries_still_escalates() {
313        // The exact shape measured live (research/zbanks-alttp.md, "The door
314        // D 0x80 stall in room $0123" and "Recovery's cap never engaged"):
315        // `stalled` is true right when a recovery fires, false on the very
316        // next tick (retry_all_given_up's zb_goal_add clears manual_mode as
317        // a side effect), then true again once the same unfixable goal
318        // fails a second time. Under the old rule every one of these was
319        // "attempt 1"; this must escalate 1..CAP and give up.
320        let mut s = Schedule::default();
321        let mut attempts = Vec::new();
322        let mut frame = 0u32;
323        for _ in 0..CAP {
324            attempts.push(s.poll(frame, true, false));
325            frame += 1;
326            s.poll(frame, false, false); // the momentary "not stalled" tick
327            frame += BACKOFF[BACKOFF.len() - 1] + 1; // always past the next backoff
328        }
329        assert_eq!(attempts, vec![Some(1), Some(2), Some(3), Some(4), Some(5)]);
330        assert!(s.gave_up);
331    }
332
333    // `Recovery`'s own progress computation (`progressed`), tested without a
334    // real Bot/Console - see the type's doc comment for why a completed goal
335    // alone is not trusted.
336
337    const HERE: (Place, u16, u16) = (Place::Indoors(0x0123), 0x5a88, 0x2447);
338    const THERE: (Place, u16, u16) = (Place::Indoors(0x0123), 0x5a78, 0x24c0);
339
340    #[test]
341    fn a_completed_goal_alone_is_not_progress_if_link_never_moved() {
342        // The live incident: a goal completes (retry_all_given_up re-added
343        // one whose target the save already satisfied) but Link's own
344        // position - the ground truth - never changed. Not progress.
345        let before: Reading = (vec![1, 2, 3], 5, HERE);
346        let after: Reading = (vec![1, 2, 3], 6, HERE);
347        assert!(!progressed(&before, &after));
348    }
349
350    #[test]
351    fn a_completed_goal_together_with_a_move_is_progress() {
352        // A goal completes AND Link is somewhere he was not - he genuinely
353        // reached new ground, not a re-evaluation of stale state.
354        let before: Reading = (vec![1, 2, 3], 5, HERE);
355        let after: Reading = (vec![1, 2, 3], 6, THERE);
356        assert!(progressed(&before, &after));
357    }
358
359    #[test]
360    fn a_possession_change_alone_is_progress_even_without_moving() {
361        // Link cannot gain an item, key, pendant or crystal without being at
362        // its location, so this signal is trusted on its own.
363        let before: Reading = (vec![1, 2, 3], 5, HERE);
364        let after: Reading = (vec![1, 2, 4], 5, HERE);
365        assert!(progressed(&before, &after));
366    }
367
368    #[test]
369    fn moving_alone_with_nothing_else_changing_is_not_progress() {
370        // Position alone, with no possession and no completed goal, is not
371        // enough either - wandering without achieving anything is not the
372        // kind of progress the cap should forgive.
373        let before: Reading = (vec![1, 2, 3], 5, HERE);
374        let after: Reading = (vec![1, 2, 3], 5, THERE);
375        assert!(!progressed(&before, &after));
376    }
377
378    #[test]
379    fn the_live_sequence_escalates_instead_of_resetting_to_one() {
380        // Reproduces research/zbanks-alttp.md's "The door D 0x80 stall in
381        // room $0123" / the live window's own recovery log: three real
382        // recoveries at frames 16567, 33125 and 49683, Link's position
383        // frozen at HERE the entire time, each with the bot's global
384        // completed-goal count having ticked up in between (a stale,
385        // already-satisfied goal re-completing on re-add). This exercises
386        // `progressed` specifically, continuously stalled throughout - the
387        // OTHER, larger half of the real fix (the `stalled` toggling off
388        // between recoveries and being wrongly read as "fixed") is
389        // `a_stall_that_clears_with_no_progress_keeps_escalating_on_recurrence`
390        // above; both were needed for the live incident to actually resolve.
391        // With position required alongside a completed goal, none of the
392        // three counts as progress here, and the schedule escalates 1, 2, 3,
393        // then continues toward the cap on the same unfixed stall.
394        let mut schedule = Schedule::default();
395        let mut baseline: Reading = (vec![0; 4], 0, HERE);
396        let mut completed = 0u64;
397        let mut attempts = Vec::new();
398        for frame in [16567u32, 33125, 49683, 66241, 82799] {
399            completed += 1; // some unrelated, trivially re-completed goal
400            let now: Reading = (baseline.0.clone(), completed, HERE); // Link never moves
401            let is_progress = progressed(&baseline, &now);
402            baseline = now;
403            attempts.push(schedule.poll(frame, true, is_progress));
404        }
405        assert_eq!(attempts, vec![Some(1), Some(2), Some(3), Some(4), Some(5)]);
406        assert!(schedule.gave_up, "the cap must be reachable on this exact sequence, not perpetually reset");
407    }
408}