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.
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.
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,
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.
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.
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.
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.
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}