jevsnes.git / packages / zbanks / src / recovery.rs

Recovering from a stall the bot's own retry mechanism cannot reach.

Bot::retry_all_given_up (called by watch_given_up on every tick) already puts a goal the bot gave up on back on the list - but only when Link's possessions change, which is the right trigger for "a goal that needed a new key" and the wrong one for a goal that keeps failing for a reason no possession change will ever touch. Measured (research/zbanks-alttp.md, the door D 0x80 stall in dungeon room $0123): the SAME GOTO_POINT failed five times, about 127 frames apart, until the planner had nothing left to score and gave up - Link was standing still the whole time, so watch_given_up never had a possession change to fire on, and the bot never tried again.

[Recovery] is the same retry - [crate::Bot::retry_all_given_up], unconditional on a possession change - triggered whenever the CALLER says the bot is stalled (crate::stall::Detector in the window, or bare manual_mode headless), bounded so it cannot spin forever on a goal that is failing for a real, unfixable reason: escalating backoff between attempts, and a cap of attempts that make no progress (a new item, key, or completed goal) before it gives up for good and says so loudly. It lives here, not in apps/native, so apps/zbanks (headless) gets the exact same mechanics rather than a second, divergent implementation.

24use alttp::Place;
25use console::Console;
27use crate::{Bot, possessions};

How many recoveries with no progress before giving up for good, for the life of this [Recovery] (a fresh one, like a fresh [Bot], only comes from a restart - the same one-way-latch shape as stall::Detector's own per-process reset).

33pub const CAP: u32 = 5;

Frames to wait before each numbered attempt: the Nth attempt (1-based) waits BACKOFF[N-1], and the schedule holds at its last entry after that. Doubling from about ten seconds (600 / 60.0988) up to roughly stall::STALL_FRAMES (five minutes), so a goal that fails fast is 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];

One attempted recovery, for the log, the panel and the bot MCP tool.

43#[derive(Clone, Copy, Debug, PartialEq, Eq)]
44pub struct Event {

The frame the attempt was made on.

46    pub frame: u32,

1-based: which numbered attempt since the last progress (or since the stall started, if there has been none).

49    pub attempt: u32,

How many goals retry_all_given_up actually put back on this try.

51    pub restored: usize,

This attempt reached [CAP]: recovery will not try again.

53    pub gave_up: bool,
54}

The pure backoff/cap decision - frame, whether the caller currently considers the bot stalled, and whether the bot has made progress since the last attempt - kept apart from [Recovery] so it can be tested without a real bot, console or C.

Only progressed==true forgets the count - NOT a bare stalled==false reading. The earlier design reset on !stalled alone, on the theory that a stall clearing at all was evidence something was fixed; it is not, when the very thing that cleared it is retry_all_given_up mechanically adding a goal back (which clears ap_manual_mode as a side effect, crate::Bot::watch_given_up's zb_goal_add) regardless of whether that goal can actually succeed. Measured live (research/zbanks-alttp.md, "Recovery's cap never engaged" and "The door D 0x80 stall"): a recovered goal that cannot succeed fails again a few hundred to ~16,500 frames later, stalled toggles back to true, and under the old rule every such cycle started a "fresh" stall at attempt 1 - forever, because the toggle itself was read as proof of a fix. Held across the toggle instead, the count escalates and reaches [CAP] on a stall that keeps recurring for the same unfixed reason, exactly as intended.

76#[derive(Default)]
77struct Schedule {
78    attempts: u32,
79    next_at: Option<u32>,
80    gave_up: bool,
81}
83impl Schedule {

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}

What the panel and the bot tool show: the last attempt, if any, and 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}

One reading of everything [Recovery] judges progress from.

128type Reading = (Vec<u8>, u64, (Place, u16, u16));

The pure half of what counts as progress - kept apart from [Recovery] so it can be tested without a real [Bot]/[Console]. See the doc on [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}

Drives [Schedule] against a real [Bot]: what counts as progress and the actual retry call.

Progress is [possessions] changing (Link cannot gain an item, key, pendant or crystal without being at its location, so this alone is trustworthy) OR the bot's own completed-goal count changing TOGETHER WITH Link's own position having moved since the last check. A completed goal on its own is not trustworthy: retry_all_given_up re-adds every given-up goal from scratch (attempts reset to 0), and one whose target the save already satisfies - a chest already opened, a door already unlocked - can leave the bot's goal list "complete" on its very first re-evaluation, before Link takes a single step. Measured live (research/zbanks-alttp.md, the door D 0x80 stall in room $0123): three real recoveries (frames 16567, 33125, 49683, then 66241, 82799, 99357, 115915 - exactly 16558 frames apart, every time, a deterministic replay of the same 33 restored goals) each logged "attempt":1, never escalating, because the completed-goal count alone kept resetting the counter although Link's own position never changed once across any of them. Gating a completed goal on a position change closes exactly that hole without discarding the signal entirely: a goal that completes because Link genuinely reached somewhere new still counts. This alone, however, is not what made the live incident loop forever - see [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}
169impl Recovery {
170    pub fn new() -> Self {
171        Self::default()
172    }

Call once a frame with whatever the caller currently considers a stall, and Link's current position (the same reading the caller already took for its own stall::Signal, so this crate does not duplicate the WRAM-position read). Cheap when nothing is due - a byte comparison and a frame check - and only calls into the C (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    }
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}