From 49b4f7b55ee5f3102c4852bc543e1318f6a60ef5 Mon Sep 17 00:00:00 2001 From: grom Date: Thu, 22 Oct 2026 20:12:03 -0600 Subject: [PATCH] ui+app: say what a fired event reached, and whether the UI answered MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit grom's stale-minimap report survived the same-interior-skip fix, and his log says why that fix was the wrong suspect: at the gate the zone-text interior claim reads `outdoors`, so the skip was never consulted there. The module doc no longer claims otherwise. What his run leaves is sharper and stranger. The election cannot have declined — leaf 1537 → 809 "Gates of Ironforge" takes the zone from 1537 to 1 and the subzone text with it, so both `ZONE_CHANGED_NEW_AREA` and `MINIMAP_ZONE_CHANGED` fire — and two separate addons call `SetMapToCurrentZone()` on those while the map is closed (`pfQuest/map.lua:1466`, `pfUI/modules/minimap.lua:183`). Zero calls arrived, with nothing raised anywhere in the session. Offline, against the same addons and saved variables, both events reach every registered handler and are answered every time, so the difference is live-only and the engine cannot currently see which of three things it is. So it can now. `UiScript::fire_event_reach` answers an `EventReach` — frames registered when the dispatch began, frames whose handler ran, and the name of the frame a cut-short walk stopped on (our documented deviation: a handler that unregisters the walk's saved next ends the dispatch, and every later registrant silently never hears the event). `UiScript::frame_shown` reads the shown bit addons branch on, which no amount of engine-side logging could otherwise explain. `fire_event` is unchanged for its nineteen callers. `area::feed_zone_events` logs the whole handshake at each fire: what was elected, reached/registered per event, the `SetMapToCurrentZone` delta, and `WorldMapFrame`'s shown bit. `0/0` is nothing registered, `reached` below `registered` is a cut-short walk, and every handler run with `0×` asked is the guard both answerers share. `addon_harness --fire` reports the reach too. Gates green (459 s). His corpus offline: 10/10, 8/8 and 4/4 handlers reached. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/src/addon_harness/probe.rs | 13 ++- crates/benilla-app/src/area.rs | 76 +++++++++++---- crates/benilla-ui/src/script/mod.rs | 15 +++ crates/benilla-ui/src/script/tests/events.rs | 92 +++++++++++++++++++ crates/benilla-ui/src/script/tick.rs | 47 +++++++++- 5 files changed, 216 insertions(+), 27 deletions(-) diff --git a/crates/benilla-app/src/addon_harness/probe.rs b/crates/benilla-app/src/addon_harness/probe.rs index 33d9cf01..493ca5e0 100644 --- a/crates/benilla-app/src/addon_harness/probe.rs +++ b/crates/benilla-app/src/addon_harness/probe.rs @@ -173,7 +173,7 @@ fn run_steps(script: &mut UiScript, steps: &[Step]) -> Vec<(String, String)> { Step::Fire(event) => { let before = script.errors().len(); let asked = script.world_map_resolver_calls(); - script.fire_event(event, vec![]); + let reach = script.fire_event_reach(event, vec![]); let raised: Vec = script.errors().into_iter().skip(before).collect(); let asks = script.world_map_resolver_calls() - asked; let what = if raised.is_empty() { @@ -183,7 +183,16 @@ fn run_steps(script: &mut UiScript, steps: &[Step]) -> Vec<(String, String)> { }; ( format!("--fire {event}"), - format!("= {what} \u{b7} SetMapToCurrentZone called {asks}\u{d7}"), + format!( + "= {what} \u{b7} reached {}/{} registered handler(s){} \u{b7} \ + SetMapToCurrentZone called {asks}\u{d7}", + reach.reached, + reach.registered, + match &reach.cut_at { + Some(name) => format!(" \u{2014} cut short at {name}"), + None => String::new(), + } + ), ) } Step::Mouse(x, y) => { diff --git a/crates/benilla-app/src/area.rs b/crates/benilla-app/src/area.rs index d0bb2904..db6e300f 100644 --- a/crates/benilla-app/src/area.rs +++ b/crates/benilla-app/src/area.rs @@ -32,10 +32,14 @@ //! happens while the player stays inside one group — walking out through Ironforge's gate //! tunnel, where the leaf goes 1537 → 809 "Gates of Ironforge" (zone Dun Morogh) under one //! unbroken group. The reference cannot be doing that: it splashes "Dun Morogh" on the way out, -//! and `GetZoneText` is how it does so. Chosen on that evidence rather than traced, and it is the -//! whole of grom's 2026-10-22 report — `ZONE_CHANGED_NEW_AREA` never fired, so nothing told -//! pfQuest to reselect the map and every minimap pin kept projecting onto the zone behind -//! (`crate::ui_world_map`'s selection watchdog is what named it). +//! and `GetZoneText` is how it does so. Chosen on that evidence rather than traced. +//! +//! It is **not** what grom's 2026-10-22 stale-minimap report was: the run after it reproduced the +//! report with the zone-text interior claim reading `outdoors` at the gate, so the skip was never +//! consulted there. What that run did establish is narrower and stranger — the election fires and +//! not one of the handlers registered for it asks to follow the player, with nothing raised. The +//! fire site logs the whole handshake for that reason; `fire_event_reach` and `frame_shown` exist +//! to make its three readings tell apart. //! //! The reference's PvP display gate `[0x88272c]` (a cached boolean, not the realm type) is //! untraced; ours is always open. @@ -275,24 +279,56 @@ fn feed_zone_events( return; } - if let Some(event) = event { - script.fire_event(event, vec![]); - if reused_names { - // Rare, and worth a line at INFO: the terrain leaf changed zone while the player - // stayed inside one interior group, which is the case the skip used to swallow. - info!( - "area: {event} inside one interior group — the terrain zone changed under it, now {:?}", - signal.zone_text - ); - } - debug!( - "area: {event} → zone {:?} / sub {:?} ({pvp_type})", - signal.zone_text, signal.subzone_text + // The whole handshake on one line, because a crossing is rare and this is the only place both + // halves of it are visible: what the engine elected, how many registered handlers each fire + // actually reached, and whether any of them answered by asking to follow the player + // (`SetMapToCurrentZone`, which seats every map-derived overlay — see `ui_world_map`'s + // watchdog, whose warning this line is the other half of). A crossing where the verb is never + // called leaves pfQuest's minimap pins a zone behind, and the three reasons it can go uncalled + // read apart here and nowhere else: `0/0` is nothing registered, `reached` below `registered` + // is a walk cut short, and every handler run with `0×` asked is the guard both answerers + // share — `shown=Some(true)` on a map the player cannot see is that guard shut + // (`pfQuest/map.lua:1466`, `pfUI/modules/minimap.lua:183`). + let asks_before = script.world_map_resolver_calls(); + let zone_reach = event.map(|e| script.fire_event_reach(e, vec![])); + let minimap_reach = + minimap_changed.then(|| script.fire_event_reach("MINIMAP_ZONE_CHANGED", vec![])); + if let (true, Some(event)) = (reused_names, event) { + // Rare, and worth a line at INFO: the terrain leaf changed zone while the player stayed + // inside one interior group, which is the case the skip used to swallow. + info!( + "area: {event} inside one interior group \u{2014} the terrain zone changed under it, now {:?}", + signal.zone_text ); } - if minimap_changed { - script.fire_event("MINIMAP_ZONE_CHANGED", vec![]); - debug!("area: minimap zone text → {minimap_text:?}"); + { + let reach = |r: Option| match r { + Some(r) => format!( + "{}/{} handler(s){}", + r.reached, + r.registered, + match r.cut_at { + // The walk stopped here: every frame after this one in the registration order + // never heard the event, and this names the addon that took it out. + Some(name) => format!(" \u{2014} cut short at {name}"), + None => String::new(), + } + ), + None => "not fired".to_string(), + }; + info!( + "area: {} \u{b7} MINIMAP_ZONE_CHANGED {} \u{b7} zone {:?} / sub {:?} ({pvp_type}) \u{b7} \ + the UI asked to follow the player {}\u{d7} \u{b7} WorldMapFrame shown={:?}", + match event { + Some(e) => format!("{e} {}", reach(zone_reach)), + None => "no zone event elected".to_string(), + }, + reach(minimap_reach), + signal.zone_text, + signal.subzone_text, + script.world_map_resolver_calls().saturating_sub(asks_before), + script.frame_shown("WorldMapFrame"), + ); } cache.zone_id = Some(signal.zone_id); cache.zone_text = signal.zone_text; diff --git a/crates/benilla-ui/src/script/mod.rs b/crates/benilla-ui/src/script/mod.rs index ff6c0910..0d389295 100644 --- a/crates/benilla-ui/src/script/mod.rs +++ b/crates/benilla-ui/src/script/mod.rs @@ -73,6 +73,7 @@ mod tick_prof; pub use event_prof::EventRow; pub use handler_prof::HandlerRow; pub use raise_prof::RaiseRow; +pub use tick::EventReach; pub use tick_prof::{Phase as TickPhase, TickPhaseRow, TimerSiteRow}; mod surface; @@ -1418,6 +1419,20 @@ impl UiScript { std::mem::take(&mut self.model_mut().notices) } + /// The named frame's own shown bit, as `frame:IsShown()` reads it (`None`: no frame owns that + /// name). Visibility is not the same question — a shown frame under a hidden parent draws + /// nothing — and this is the shown bit, because that is the one addons branch on. + /// + /// The engine needs it to read its own log: both addons that answer `ZONE_CHANGED*` by + /// reselecting the world map do it only `if not WorldMapFrame:IsShown()` + /// (`pfQuest/map.lua:1466`, `pfUI/modules/minimap.lua:183`), so one shown bit left set + /// silences both — with no error, no call, and nothing in the VM that says so. + pub fn frame_shown(&self, name: &str) -> Option { + let model = self.model_ref(); + let h = model.arena.lookup(name)?; + Some(model.arena.frame(h)?.shown) + } + /// Report a script error the host caught outside the VM's dispatch (an addon file that failed /// to compile or raised at file scope): it joins the handler-dispatch queue and the retained /// log, not `errors`, since the caller has already logged it. diff --git a/crates/benilla-ui/src/script/tests/events.rs b/crates/benilla-ui/src/script/tests/events.rs index f64b599a..9a8011aa 100644 --- a/crates/benilla-ui/src/script/tests/events.rs +++ b/crates/benilla-ui/src/script/tests/events.rs @@ -441,3 +441,95 @@ fn a_raising_handlers_message_carries_its_line_and_a_stack_traceback() { "the trampoline must hand the error object back, not `tostring` it and wrap it again: {host}" ); } + +/// The reach the fire answers with ([`EventReach`]), which is how the engine tells an event +/// nothing is registered for from one whose handlers all ran and did nothing. +#[test] +fn the_reach_counts_the_registered_frames_and_the_handlers_that_ran() { + let mut s = script(); + s.run( + r#" + for _, n in ipairs({"RchA", "RchB", "RchC"}) do + local f = CreateFrame("Frame", n) + f:RegisterEvent("E_REACH") + f:SetScript("OnEvent", function() end) + end + "#, + ) + .unwrap(); + assert_eq!( + s.fire_event_reach("E_REACH", vec![]), + EventReach { + registered: 3, + reached: 3, + cut_at: None + } + ); + // Nothing registered reads as 0/0, not as a dispatch that reached nobody for another reason. + assert_eq!( + s.fire_event_reach("E_NOBODY_WANTS", vec![]), + EventReach { + registered: 0, + reached: 0, + cut_at: None + } + ); +} + +/// A walk cut short by a handler unregistering the saved next, which +/// `mid_dispatch_removal_of_the_next_stops_and_append_is_visited` above pins as the behaviour, +/// reads as `reached` below `registered` — the symptom being a frame late in the list that never +/// hears an event it is registered for, with nothing raised anywhere. +#[test] +fn a_walk_cut_short_reaches_fewer_handlers_than_are_registered() { + let mut s = script(); + s.run( + r#" + local function reg(n, body) + local f = CreateFrame("Frame", n) + f:RegisterEvent("E_CUT") + f:SetScript("OnEvent", function() if body then body() end end) + end + reg("CutA", function() CutB:UnregisterEvent("E_CUT") end) + reg("CutB") + reg("CutC") + "#, + ) + .unwrap(); + // `cut_at` names the registration that was taken out from under the walk, which is the whole + // point: the two counts say a dispatch was cut short, the name says by whom. + assert_eq!( + s.fire_event_reach("E_CUT", vec![]), + EventReach { + registered: 3, + reached: 1, + cut_at: Some("CutB".to_string()) + } + ); + assert!(s.errors().is_empty(), "{:?}", s.errors()); +} + +/// [`UiScript::frame_shown`] is the shown bit addons branch on, by name, including for a frame +/// whose parent is hidden — `IsShown` and `IsVisible` are different questions and this is the +/// first. An unknown name is `None`, which is not the same answer as a hidden frame. +#[test] +fn frame_shown_reads_the_named_frames_own_shown_bit() { + let s = script(); + s.run( + r#" + local parent = CreateFrame("Frame", "ShownParent") + local child = CreateFrame("Frame", "ShownChild", parent) + CreateFrame("Frame", "ShownHidden"):Hide() + parent:Hide() + "#, + ) + .unwrap(); + assert_eq!(s.frame_shown("ShownParent"), Some(false)); + // Shown under a hidden parent: not visible, still shown. + assert_eq!(s.frame_shown("ShownChild"), Some(true)); + assert!(!s + .eval::("return ShownChild:IsVisible() and true or false") + .unwrap()); + assert_eq!(s.frame_shown("ShownHidden"), Some(false)); + assert_eq!(s.frame_shown("NoSuchFrameAnywhere"), None); +} diff --git a/crates/benilla-ui/src/script/tick.rs b/crates/benilla-ui/src/script/tick.rs index c8017407..d245aaf4 100644 --- a/crates/benilla-ui/src/script/tick.rs +++ b/crates/benilla-ui/src/script/tick.rs @@ -14,6 +14,27 @@ use crate::widget::FrameHandle; use super::tick_prof::{Phase, Split, Tally}; use super::{editbox, event, tooltip, Model, ScriptValue, UiScript}; +/// What one [`UiScript::fire_event`] reached: how many frames were on the event's list when the +/// dispatch began, and how many of their handlers ran. The two differ only where the walk ended +/// early, which is a handler having unregistered the frame the walk saved as its next (see +/// [`UiScript::fire_event`]). +/// +/// It exists because "the event never arrived", "the list was cut short before the frame that acts +/// on it" and "every handler ran and none of them acted" have one symptom — a UI verb nobody +/// called — and three different fixes. Only the engine can see which, and only at the fire. +#[derive(Debug, Clone, Default, PartialEq, Eq)] +pub struct EventReach { + /// Frames registered for the event when the dispatch began. + pub registered: usize, + /// Frames whose handler actually ran. Less than `registered` is a cut-short walk; a handler + /// that raised still counts, because it ran. + pub reached: usize, + /// The frame the walk stopped on, named if it has a name: the registration a handler had just + /// removed. `None` when the walk ran to the end. It names the addon to look at, which the two + /// counts alone cannot. + pub cut_at: Option, +} + impl UiScript { /// Queue an event for the start of the next tick, behind everything queued earlier and before /// that tick's `OnUpdate` pass. A drain runs a step behind its input, so firing at once would @@ -38,22 +59,29 @@ impl UiScript { pub fn fire_event(&mut self, event: &str, args: Vec) { fire_event_into(&self.lua, event, args); } + + /// [`Self::fire_event`], answering what the dispatch reached ([`EventReach`]). Nothing about + /// the fire changes; the number is simply kept rather than dropped, for the one caller that + /// has to explain a silent event afterwards (`benilla-app`'s `area::feed_zone_events`). + pub fn fire_event_reach(&mut self, event: &str, args: Vec) -> EventReach { + fire_event_into(&self.lua, event, args) + } } /// [`UiScript::fire_event`] for a caller holding `&Lua`, such as a Lua binding. -pub(crate) fn fire_event_into(lua: &Lua, event: &str, args: Vec) { +pub(crate) fn fire_event_into(lua: &Lua, event: &str, args: Vec) -> EventReach { let model_mut = || lua.app_data_mut::().expect("model app_data set"); // `WOW_UI_EVENTS=`: this whole fan-out is one fire of `event`, which is the unit a // dropped frame is measured in. Inert and one atomic load unarmed. let _dispatch = super::event_prof::armed().then(|| super::event_prof::Dispatch::open(lua, event)); + let mut reach = EventReach::default(); { let mut at = { let model = model_mut(); - model - .event_to_frames - .get(event) - .and_then(|l| l.first().copied()) + let list = model.event_to_frames.get(event); + reach.registered = list.map_or(0, Vec::len); + list.and_then(|l| l.first().copied()) }; while let Some(h) = at { let mut model = model_mut(); @@ -63,6 +91,13 @@ pub(crate) fn fire_event_into(lua: &Lua, event: &str, args: Vec) { .get(event) .and_then(|l| l.iter().position(|&x| x == h)) else { + reach.cut_at = Some( + model + .arena + .frame(h) + .and_then(|f| f.name.clone()) + .unwrap_or_else(|| "an unnamed frame".to_string()), + ); break; }; let next = model @@ -71,6 +106,7 @@ pub(crate) fn fire_event_into(lua: &Lua, event: &str, args: Vec) { .and_then(|l| l.get(pos + 1).copied()); let id = model.frame_id(h); drop(model); + reach.reached += 1; if let Err(e) = event::fire_event_handler(lua, id, event, &args) { model_mut().record_script_error(e.to_string()); } @@ -78,6 +114,7 @@ pub(crate) fn fire_event_into(lua: &Lua, event: &str, args: Vec) { } } event::fire_all_event_listeners(lua, event, &args); + reach } impl super::UiScript {