From d1edd74cce096274ea19bbe22c3f85dff657ca60 Mon Sep 17 00:00:00 2001 From: grom Date: Mon, 2 Nov 2026 07:21:48 -0700 Subject: [PATCH] ui: a runaway frame writes its own line, and stops costing the whole bound twice MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- .../benilla-app/src/ui_script/extract/mod.rs | 7 ++ crates/benilla-ui/src/script/mod.rs | 73 +++++++++++++++++-- crates/benilla-ui/src/script/stdlib.rs | 7 +- .../src/script/tests/runaway_frame.rs | 66 +++++++++++++++++ 4 files changed, 147 insertions(+), 6 deletions(-) diff --git a/crates/benilla-app/src/ui_script/extract/mod.rs b/crates/benilla-app/src/ui_script/extract/mod.rs index 21e61e45..1adc4313 100644 --- a/crates/benilla-app/src/ui_script/extract/mod.rs +++ b/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}"); } diff --git a/crates/benilla-ui/src/script/mod.rs b/crates/benilla-ui/src/script/mod.rs index 060923a9..70158b8b 100644 --- a/crates/benilla-ui/src/script/mod.rs +++ b/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, + /// 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>>, 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\\`, /// 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 { + 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. diff --git a/crates/benilla-ui/src/script/stdlib.rs b/crates/benilla-ui/src/script/stdlib.rs index b3eaa70b..9c614c86 100644 --- a/crates/benilla-ui/src/script/stdlib.rs +++ b/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; diff --git a/crates/benilla-ui/src/script/tests/runaway_frame.rs b/crates/benilla-ui/src/script/tests/runaway_frame.rs index c1e7f57a..cfa74903 100644 --- a/crates/benilla-ui/src/script/tests/runaway_frame.rs +++ b/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::("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:?}" + ); +}