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}