ui: a runaway frame writes its own line, and stops costing the whole bound twice

Two of his sessions froze this morning with nothing in the log. The journal
says what happened: every frame 15,0xx ms, `main_ms` 14,970 of it, GPU 3 ms,
the main thread `state R` with 64 s of CPU in 68 s of wall. That dead-constant
15.02 s is `RUNAWAY_FRAME_SECS` — a Lua loop that never returns, re-entered the
next frame and the next.

The bound did its job and said nothing, because its raise unwinds to whatever
`pcall` caught the call. On this corpus that is always an addon's own guard, so
the trip became nobody's script error: `session errors: 0`, no log line, no
file, no line number. `WOW_UI_RAISES` would have caught it and is `eprintln!`
only, which is no use to someone who is in the game.

So the hook writes its own report before raising, and the host logs it at
`error!` beside the ordinary error drain. Each kept report carries a sixteen
frame traceback, because the innermost line is usually inside a library and the
handler that entered the loop is the name worth having.

And the bound tightens to a second once it has tripped. The first one has to be
far beyond any legitimate frame, which makes it far beyond playable: a loop is
re-entered every frame, so the player gets one frame every fifteen seconds —
indistinguishable from the freeze the bound exists to prevent, and that is
exactly what he got. One trip has already proved the call non-terminating; the
ones after it need only enough rope to say so. A second is still some 125M VM
instructions, two orders past the heaviest handler ever measured here.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn

crates/benilla-app/src/ui_script/extract/mod.rs

@@ -567,6 +567,13 @@ pub(super) fn tick_script(
     for err in script.take_errors() {
         warn!("ui_script: {err}");
     }
+    // The runaway bound writes its own line, because its raise unwinds into whatever `pcall` the
+    // loop was called under and usually becomes nobody's error. Without this a frame stuck in Lua
+    // costs the bound's whole 15 s, every frame, and leaves the log silent — which is exactly what
+    // two frozen sessions handed back.
+    for r in script.take_runaway_reports() {
+        error!("ui_script: {r}");
+    }
     for w in script.take_warnings() {
         warn!("ui_script: {w}");
     }

crates/benilla-ui/src/script/mod.rs

@@ -553,6 +553,9 @@ pub struct UiScript {
     /// When this frame's Lua began, for [`UiScript::set_runaway_limit`]; nanoseconds on
     /// [`mono_nanos`]'s clock, shared with the hook closure.
     vm_entry: std::sync::Arc<std::sync::atomic::AtomicU64>,
+    /// Every runaway-frame bound [`UiScript::set_runaway_limit`] has tripped, written by the hook
+    /// itself so [`UiScript::take_runaway_reports`] can hand the host a line no `pcall` can eat.
+    runaways: std::sync::Arc<std::sync::Mutex<Vec<String>>>,
     session: u64,
 }
 
@@ -571,6 +574,26 @@ static NEXT_SESSION: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64
 /// How often the instruction hook fires: an instruction budget's resolution (low values cost).
 pub const INSTRUCTION_HOOK_STEP: u32 = 1_000_000;
 
+/// How many runaway-frame reports one VM keeps for the host ([`UiScript::set_runaway_limit`]). A
+/// loop that never terminates trips the bound on every frame after the first, and the first few
+/// name the line just as well as a thousand would.
+const RUNAWAY_REPORTS_KEPT: usize = 8;
+
+/// What the runaway bound shrinks to once it has tripped ([`UiScript::set_runaway_limit`]).
+///
+/// The first bound has to be far beyond any legitimate frame, which makes it far beyond playable:
+/// a loop that never terminates is re-entered every frame, so the player gets one frame every 15
+/// seconds — indistinguishable from the freeze the bound exists to prevent, and grom's two frozen
+/// sessions were exactly that. One trip has already proved the loop non-terminating, so every
+/// trip after it can be cut short: a second long Lua frame in one session is not a thing that
+/// happens, and 1 s is still some 125M VM instructions, two orders beyond the heaviest handler
+/// ever measured here (15.8 ms). The client then runs at ~1 fps instead of 0.07, which is the
+/// difference between `/reload`-and-disable-the-addon and killing the process.
+///
+/// Capped at a quarter of the bound actually armed, so a player who set a short one with
+/// `WOW_LUA_RUNAWAY` still sees it tighten rather than loosen.
+const RUNAWAY_REPEAT_SECS: f64 = 1.0;
+
 /// The chunk name the 1.12 client gives an addon's file, `Interface\AddOns\<Folder>\<File>`,
 /// backslashed and with the file, because addons parse it: `FuBarPlugin-2.0` finds its folder with
 /// the greedy `\\AddOns\\(.*)\\` over `debugstack`, which needs the file after the folder.
@@ -702,6 +725,7 @@ impl UiScript {
             lua,
             instructions: std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0)),
             vm_entry: std::sync::Arc::new(std::sync::atomic::AtomicU64::new(mono_nanos())),
+            runaways: std::sync::Arc::new(std::sync::Mutex::new(Vec::new())),
             session: NEXT_SESSION.fetch_add(1, std::sync::atomic::Ordering::Relaxed),
         };
         Ok(s)
@@ -772,34 +796,73 @@ impl UiScript {
     pub fn set_runaway_limit(&self, limit: std::time::Duration) {
         let entry = self.vm_entry.clone();
         entry.store(mono_nanos(), std::sync::atomic::Ordering::Relaxed);
-        let limit_ns = u64::try_from(limit.as_nanos()).unwrap_or(u64::MAX);
+        // Shared rather than captured by value, because the first trip tightens it: see
+        // [`RUNAWAY_REPEAT_SECS`].
+        let armed_ns = u64::try_from(limit.as_nanos()).unwrap_or(u64::MAX);
+        let limit_ns = std::sync::Arc::new(std::sync::atomic::AtomicU64::new(armed_ns));
+        let reports = self.runaways.clone();
         let _ = self.lua.set_hook(
             mlua::HookTriggers {
                 every_nth_instruction: Some(INSTRUCTION_HOOK_STEP),
                 ..Default::default()
             },
-            move |_, debug| {
+            move |lua, debug| {
                 let started = entry.load(std::sync::atomic::Ordering::Relaxed);
                 let now = mono_nanos();
                 let spent = now.saturating_sub(started);
-                if spent <= limit_ns {
+                let bound = limit_ns.load(std::sync::atomic::Ordering::Relaxed);
+                if spent <= bound {
                     return Ok(mlua::VmState::Continue);
                 }
+                // This trip has proved the call non-terminating; the ones after it need only
+                // enough rope to say so.
+                let repeat_ns = ((RUNAWAY_REPEAT_SECS * 1e9) as u64).min(armed_ns / 4);
+                if bound > repeat_ns {
+                    limit_ns.store(repeat_ns, std::sync::atomic::Ordering::Relaxed);
+                }
                 // Restamp before raising: the error unwinds to whatever pcall caught the call, and
                 // the rest of the frame — and every frame after it — deserves a whole budget.
                 entry.store(now, std::sync::atomic::Ordering::Relaxed);
                 let src = debug.source();
-                Err(mlua::Error::runtime(format!(
+                let msg = format!(
                     "benilla: {:.1} s inside Lua in one frame, at {}:{} — treating it as a \
                      non-terminating loop and failing the call, so the client keeps running",
                     spent as f64 / 1e9,
                     src.short_src.as_deref().unwrap_or("?"),
                     debug.current_line().unwrap_or(0),
-                )))
+                );
+                // Write it down before raising. The raise unwinds to whatever `pcall` caught the
+                // call — an addon's own guard, usually — and a swallowed raise reaches no log at
+                // all, which is how two frozen sessions produced a 15 s frame every frame and not
+                // one line naming the loop. `try_lock` because a hook must never block: the host
+                // reads this between frames, so contention means another VM's thread, not ours.
+                if let Ok(mut r) = reports.try_lock() {
+                    // A bound that trips every frame says the same thing every frame; keep the
+                    // first few lines, not a session's worth of them. The traceback is built only
+                    // for the ones kept, because the innermost line is rarely the culprit: the
+                    // loop is in a library and the handler that entered it is what has to be named.
+                    // Level 0 is the function the hook interrupted — a hook pushes no frame of its
+                    // own — so the walk starts there rather than at `debugstack`'s default caller.
+                    if r.len() < RUNAWAY_REPORTS_KEPT {
+                        let stack = stdlib::traceback_frames(lua, 0, 16, 8);
+                        r.push(format!("{msg}\nstack traceback:\n{stack}"));
+                    }
+                }
+                Err(mlua::Error::runtime(msg))
             },
         );
     }
 
+    /// Drain what the runaway bound wrote ([`Self::set_runaway_limit`]), for the host to log.
+    /// Independent of [`Self::take_errors`], because the raise itself usually unwinds into an
+    /// addon's `pcall` and never becomes a script error at all.
+    pub fn take_runaway_reports(&self) -> Vec<String> {
+        self.runaways
+            .try_lock()
+            .map(|mut r| std::mem::take(&mut *r))
+            .unwrap_or_default()
+    }
+
     /// Restamp this frame's Lua clock for [`Self::set_runaway_limit`]. [`Self::tick`] calls it, so
     /// a host that drives the VM by hand (a test, the harness) can arm a limit and still get a
     /// fresh budget per frame.

crates/benilla-ui/src/script/stdlib.rs

@@ -740,7 +740,12 @@ fn traceback_frame(d: &mlua::Debug) -> String {
 /// Frames print while the level is `<= start + count1` (`0x703857`, `jbe`); then a failed
 /// `getstack(level + count2)` probe prints that level as an ordinary frame, else `"...\n"` and
 /// the last `count2` follow. So `count1 = 1` gives two frames on a two-deep stack, not one.
-fn traceback_frames(lua: &Lua, start: usize, count1: usize, count2: usize) -> String {
+pub(in crate::script) fn traceback_frames(
+    lua: &Lua,
+    start: usize,
+    count1: usize,
+    count2: usize,
+) -> String {
     let mut out = String::new();
     let mut level = start;
     let mut first_part = true;

crates/benilla-ui/src/script/tests/runaway_frame.rs

@@ -6,6 +6,8 @@ use std::time::Duration;
 use crate::script::UiScript;
 
 /// Short enough to keep the test instant, and far longer than the hook's 1M-instruction step.
+/// Below [`crate::script::RUNAWAY_REPEAT_SECS`], so the tests that trip once are not also
+/// measuring the tightening — [`the_bound_tightens_once_it_has_tripped`] is what reads that.
 const LIMIT: Duration = Duration::from_millis(80);
 
 #[test]
@@ -55,3 +57,67 @@ fn a_frame_is_not_charged_the_one_before_it() {
     let err = s.lua().load("while true do end").exec();
     assert!(err.is_err(), "an unmarked frame still runs out");
 }
+
+#[test]
+fn a_swallowed_runaway_still_reaches_the_host() {
+    let s = UiScript::new().expect("a VM");
+    s.set_runaway_limit(LIMIT);
+
+    // The shape that froze two live sessions and logged nothing: the loop runs under the addon's
+    // own `pcall`, so the bound's raise never becomes a script error and the host sees a 15 s
+    // frame with no line naming it.
+    s.lua()
+        .load("benilla_swallowed = pcall(function() while true do end end)")
+        .set_name("Interface\\AddOns\\Stuck\\Stuck.lua")
+        .exec()
+        .expect("the pcall catches the bound's raise, so the chunk itself succeeds");
+    assert_eq!(
+        s.lua().globals().get::<bool>("benilla_swallowed").ok(),
+        Some(false),
+        "the pcall caught it — nothing raised out of the chunk"
+    );
+    assert!(
+        s.errors().is_empty(),
+        "and it is nobody's script error: {:?}",
+        s.errors()
+    );
+
+    let reports = s.take_runaway_reports();
+    assert_eq!(reports.len(), 1, "one trip, one line: {reports:?}");
+    assert!(
+        reports[0].contains("Stuck.lua") && reports[0].contains("non-terminating loop"),
+        "the host's line names the chunk and what was decided: {}",
+        reports[0]
+    );
+    assert!(
+        s.take_runaway_reports().is_empty(),
+        "a drain empties it, so the log says it once per trip"
+    );
+}
+
+#[test]
+fn the_bound_tightens_once_it_has_tripped() {
+    let s = UiScript::new().expect("a VM");
+    s.set_runaway_limit(LIMIT);
+
+    let first = std::time::Instant::now();
+    assert!(
+        s.lua().load("while true do end").exec().is_err(),
+        "the first trip takes the whole bound"
+    );
+    let first = first.elapsed();
+
+    s.mark_vm_entry();
+    let second = std::time::Instant::now();
+    assert!(
+        s.lua().load("while true do end").exec().is_err(),
+        "and so does the second"
+    );
+    let second = second.elapsed();
+
+    // A quarter of the bound armed, so the client keeps drawing instead of reading as frozen.
+    assert!(
+        second < first / 2,
+        "the second trip is cut short: {first:?} then {second:?}"
+    );
+}