From 5a824f162561dee9870840ea714d771d9936ade4 Mon Sep 17 00:00:00 2001 From: grom Date: Sun, 25 Oct 2026 09:46:50 -0600 Subject: [PATCH] =?UTF-8?q?app:=20the=20press=20queue=20was=20switched=20o?= =?UTF-8?q?ff=20in=20play=20=E2=80=94=20a=20derived=20Default=20is=20the?= =?UTF-8?q?=20live=20config?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `cvars.rs` announces a `CvarChanged` only when a value *moves*, and `config.toml` holds only the rows that left their defaults ("CVar values that moved off their defaults" — its own header). So a row the player never touched never reaches an `on_cvar` observer, and the resource's own `Default` is what the client runs with for the whole session. `PressRules` and `SpellQueue` both derived `Default`. Every toggle was false, every window 0 and every buffer 0, so the press-interception queue held nothing, the mount refusal never fired, and `SpellQueue`'s zero window expired each explicit entry on the frame it was queued — the day after all of it was committed. Fourteen of the sixteen rows have a non-zero registered default. grom's own `WoWCombatLog.txt` is what named it, with no live run to ask for: 147 `Sunder Armor: Not yet recovered` against 163 landed Sunders, in bursts 0.17-0.23 s apart — every press refused, none held. Sunder Armor rank 1 on this realm is `rec=0 cat=0 catrec=0 gcdcat=133 gcd=1500`, read off its own `Spell.dbc`: a global cooldown and nothing else, which is precisely the case the queue must hold. Both now hand-write `Default` with the registered values, which is the pattern `cvars.rs::registered_defaults_mirror_the_code_truths` already welds for the engine knobs; `np_press.rs::the_default_is_the_registry` welds these sixteen the same way. The test-only `defaults_for_tests()` constructors are gone — they spelled out the registered numbers for tests to read while the client could not reach them, which is the whole shape of the bug. A sweep of the other nine CVar-cached resources (list every `fn on_cvar`, take its `ResMut` types, check for a hand-written `Default`, look up each CVar it names in `REGISTERED`) found no further victims. Two things so the next session can speak for itself: - `a_press_made_during_the_global_cooldown_is_held_and_sent_when_it_ends` — the end-to-end cycle with the GCD as the only guard, which is what a class with no cast bar presses into all day. The existing end-to-end test arms `PendingCast` by hand and so never starts a GCD at all; this one presses through the real ladder, so the commit arms it the way a cast does. - one `info!` a minute from the drain, and only when something moved: held, sent, dropped, retried, fell-through, channels cut — plus the live windows and buffers. Every other line this half writes is `debug!` and the default filter is INFO, so a 67-minute session could not say one word about the queue. A line of zeroed knobs now diagnoses this class of fault by itself. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01SgstFWtn1RxEJ5kVrpgYwn --- crates/benilla-app/src/spell/cast_send.rs | 16 +- crates/benilla-app/src/spell/np_press.rs | 231 ++++++++++++++++------ crates/benilla-app/src/spell/queue.rs | 147 ++++++++++++-- crates/benilla-app/src/ui_spellbook.rs | 176 ++++++++++++++++- docs/ADDON_COMPAT.md | 15 ++ 5 files changed, 502 insertions(+), 83 deletions(-) diff --git a/crates/benilla-app/src/spell/cast_send.rs b/crates/benilla-app/src/spell/cast_send.rs index 7e3b9a69..e1a20f7a 100644 --- a/crates/benilla-app/src/spell/cast_send.rs +++ b/crates/benilla-app/src/spell/cast_send.rs @@ -528,6 +528,7 @@ fn send_spell_cast( return; } debug!("np-press: holding {spell_id} as {kind:?}, giving up in {window_ms} ms"); + np.queue.note_held(now); np.queue .queue_with_window(spell_id, kind, now, guard_end(&guard), window_ms); return; @@ -541,9 +542,18 @@ fn send_spell_cast( spell_id: channelled, }); } + np.queue.note_interrupted(now); return; } - None => {} + // Declined: the press carries on down the ladder to the refusal it has earned. Worth + // counting, because a session full of these beside few holds is the queue failing to + // do the one thing it is for — and the error line the player reads says nothing about + // the queue at all. + None => { + if guard.any() { + np.queue.note_fell_through(now); + } + } } } if pending.in_flight(now) { @@ -1020,7 +1030,7 @@ mod tests { /// would refuse for a timing reason is held here. [`reference_timing_world`] is the same /// ladder with it off, for the tests whose subject is that refusal. fn world() -> (World, Receiver) { - world_with(crate::spell::np_press::PressRules::defaults_for_tests()) + world_with(crate::spell::np_press::PressRules::default()) } /// [`world`] with nampower's press queue switched off, which is what a player who unticks the @@ -1046,7 +1056,7 @@ mod tests { world.init_resource::(); world.init_resource::(); world.insert_resource(np); - world.insert_resource(crate::spell::queue::SpellQueue::defaults_for_tests()); + world.insert_resource(crate::spell::queue::SpellQueue::default()); world.init_resource::(); world.init_resource::(); // A bare World has no message storage until it is asked for. diff --git a/crates/benilla-app/src/spell/np_press.rs b/crates/benilla-app/src/spell/np_press.rs index 681c0ddf..1087d751 100644 --- a/crates/benilla-app/src/spell/np_press.rs +++ b/crates/benilla-app/src/spell/np_press.rs @@ -55,9 +55,15 @@ pub(crate) const SPELL_AURA_MOUNTED: u32 = 78; /// nampower's press-side CVar rows, applied by [`on_cvar`]. /// -/// The registry fires that observer at boot with each registered default, so no field is read -/// before it has been seeded. -#[derive(Resource, Default)] +/// **[`Default`] carries the value `cvars.rs` registers for every row, and it has to.** The +/// registry announces a `CvarChanged` only when a value *moves* — at boot that means the rows +/// `benilla-config/config.toml` overrides and nothing else, because the file holds only what left +/// its default. So a row the player never touched never reaches [`on_cvar`], and whatever +/// `Default` says is what the client runs with forever. A derived `Default` here read every +/// toggle as false and every window as 0, which is the whole queue switched off in play while +/// every test that built the resource by hand passed. +/// `tests::the_default_is_the_registry` welds the two. +#[derive(Resource)] pub(crate) struct PressRules { /// `NP_PreventMountingWhenBuffCapped`. prevent_mounting_buff_capped: bool, @@ -220,7 +226,7 @@ pub(crate) struct PressGuard { impl PressGuard { /// Whether anything at all is holding the press back. - fn any(&self) -> bool { + pub(crate) fn any(&self) -> bool { self.cast.is_some() || self.channel.is_some() || self.gcd.is_some() @@ -238,38 +244,10 @@ pub(crate) enum Press { InterruptChannel, } -impl PressRules { - /// The resource as the registry would have seeded it, for a test that runs the whole ladder - /// rather than one rule. Test-only so [`on_cvar`] stays the only writer in the app. - #[cfg(test)] - pub(crate) fn for_tests(prevent_mounting_buff_capped: bool) -> Self { - Self { - prevent_mounting_buff_capped, - ..Self::defaults_for_tests() - } - } - - /// [`Self::defaults_for_tests`] with the five admission toggles off: what a player who - /// unticks nampower's queue in its settings panel runs, and the only configuration in which - /// the reference's own timing refusals are still reachable. The buffers stay at their - /// defaults, because those rows are not the queue and a player turning the queue off does not - /// turn them off. - #[cfg(test)] - pub(crate) fn queue_off_for_tests() -> Self { - Self { - queue_cast_time: false, - queue_instant: false, - queue_channeling: false, - queue_targeting: false, - queue_on_swing: false, - ..Self::defaults_for_tests() - } - } - - /// Every row at the default `cvars.rs` registers, so a test reads the behaviour a player who - /// touched nothing gets. - #[cfg(test)] - pub(crate) fn defaults_for_tests() -> Self { +/// Every row at the value `cvars.rs` registers for it — see [`PressRules`] for why this is the +/// only place those numbers can live. +impl Default for PressRules { + fn default() -> Self { Self { prevent_mounting_buff_capped: true, queue_cast_time: true, @@ -290,6 +268,62 @@ impl PressRules { channel_latency_reduction_pct: 75, } } +} + +impl PressRules { + /// The resource as the registry would have seeded it, for a test that runs the whole ladder + /// rather than one rule. Test-only so [`on_cvar`] stays the only writer in the app. + #[cfg(test)] + pub(crate) fn for_tests(prevent_mounting_buff_capped: bool) -> Self { + Self { + prevent_mounting_buff_capped, + ..Self::default() + } + } + + /// [`Default`] with the five admission toggles off: what a player who + /// unticks nampower's queue in its settings panel runs, and the only configuration in which + /// the reference's own timing refusals are still reachable. The buffers stay at their + /// defaults, because those rows are not the queue and a player turning the queue off does not + /// turn them off. + #[cfg(test)] + pub(crate) fn queue_off_for_tests() -> Self { + Self { + queue_cast_time: false, + queue_instant: false, + queue_channeling: false, + queue_targeting: false, + queue_on_swing: false, + ..Self::default() + } + } + + /// The four windows and the two buffers, for the period line in `ui_spellbook.rs` — the one + /// place the live values are printed, so a wrongly-seeded row reads as zeroes in the log + /// instead of as a feel nobody can pin down. + pub(crate) fn window_spell_ms(&self) -> u32 { + self.window_spell_ms + } + + pub(crate) fn window_channel_ms(&self) -> u32 { + self.window_channel_ms + } + + pub(crate) fn window_cooldown_ms(&self) -> u32 { + self.window_cooldown_ms + } + + pub(crate) fn window_targeting_ms(&self) -> u32 { + self.window_targeting_ms + } + + pub(crate) fn buffer_ms(&self) -> u32 { + self.buffer_ms + } + + pub(crate) fn buffer_non_gcd_ms(&self) -> u32 { + self.buffer_non_gcd_ms + } /// The guard buffer for a spell: `NP_NonGcdBufferTimeMs` when it costs no global cooldown, /// `NP_MinBufferTimeMs` otherwise. @@ -590,8 +624,11 @@ mod tests { /// The rule's four inputs, each on its own. #[test] fn a_mount_press_is_refused_only_at_the_cap_and_only_on_the_ground() { - let on = PressRules::defaults_for_tests(); - let off = PressRules::default(); + let on = PressRules::default(); + // Explicitly, not `Default`: this row ships **on**, so "off" is a player's own + // `/console NP_PreventMountingWhenBuffCapped 0` and has to be written down as one. Reading + // it off `Default` is how this test used to pass while the registered value said otherwise. + let off = PressRules::for_tests(false); let capped = store(UNIT_AURA_POSITIVE_SLOTS, 0); assert!( @@ -627,7 +664,7 @@ mod tests { /// slots a mount aura can never use must not be mistaken for a full one. #[test] fn the_cap_counts_the_positive_half_alone() { - let on = PressRules::defaults_for_tests(); + let on = PressRules::default(); let s = store_with(UNIT_AURA_POSITIVE_SLOTS..UNIT_AURA_SLOTS, 0); assert_eq!(free_buff_slots(&s), usize::from(UNIT_AURA_POSITIVE_SLOTS)); assert!( @@ -660,7 +697,7 @@ mod tests { /// of every key, and the one that has to cost nothing and change nothing. #[test] fn a_press_with_nothing_guarding_it_is_never_held() { - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); assert_eq!( r.admit( FROSTBOLT, @@ -684,7 +721,7 @@ mod tests { r.admit(FROSTBOLT, Some(spell), cast_time, terrain, &guard, true, t0) .is_some() }; - let all_on = PressRules::defaults_for_tests(); + let all_on = PressRules::default(); // The defaults hold a cast-time press, an instant and a terrain spell, and not a strike. assert!(held(&all_on, 1_500, false, &instant()), "a cast-time press"); @@ -701,7 +738,7 @@ mod tests { // And each row, alone, takes its own class out. let without = |f: fn(&mut PressRules)| { - let mut r = PressRules::defaults_for_tests(); + let mut r = PressRules::default(); f(&mut r); r }; @@ -754,7 +791,7 @@ mod tests { fn spam_protection_swallows_a_repeat_of_the_cast_in_flight() { let t0 = Instant::now(); let guard = casting(t0, FROSTBOLT, 1_500); - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); assert_eq!( r.admit(FROSTBOLT, Some(&instant()), 1_500, false, &guard, true, t0), None, @@ -765,8 +802,10 @@ mod tests { .is_some(), "a different spell is the press the queue exists for" ); - let mut off = PressRules::defaults_for_tests(); - off.spam_protection = false; + let off = PressRules { + spam_protection: false, + ..Default::default() + }; assert!( off.admit(FROSTBOLT, Some(&instant()), 1_500, false, &guard, true, t0) .is_some(), @@ -779,7 +818,7 @@ mod tests { #[test] fn the_window_is_the_longest_guards_own() { let t0 = Instant::now(); - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); let at = |ms: u64| Some(t0 + Duration::from_millis(ms)); assert_eq!( @@ -859,14 +898,16 @@ mod tests { r.admit(FROSTBOLT, Some(&instant()), 0, false, g, true, t0) }; - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); assert!( matches!(press(&r, &long), Some(Press::Queue { .. })), "the defaults hold the press and leave the channel running" ); - let mut interrupt = PressRules::defaults_for_tests(); - interrupt.interrupt_channels_outside_window = true; + let interrupt = PressRules { + interrupt_channels_outside_window: true, + ..Default::default() + }; assert_eq!( press(&interrupt, &long), Some(Press::InterruptChannel), @@ -877,8 +918,10 @@ mod tests { "900 ms left is inside the window — nearly finished channels are worth finishing" ); - let mut no_channel_queue = PressRules::defaults_for_tests(); - no_channel_queue.queue_channeling = false; + let no_channel_queue = PressRules { + queue_channeling: false, + ..Default::default() + }; assert_eq!( press(&no_channel_queue, &long), None, @@ -899,7 +942,7 @@ mod tests { cooldown: Some(t0 + Duration::from_millis(ms)), ..Default::default() }; - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); let held = |g: &PressGuard, allowed: bool| { r.admit(FROSTBOLT, Some(&instant()), 0, false, g, allowed, t0) .is_some() @@ -925,7 +968,7 @@ mod tests { #[test] fn the_channel_guard_is_its_named_end_less_a_share_of_the_round_trip() { let t0 = Instant::now(); - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); let mut channel = super::super::ActiveChannel::default(); channel.start(FROSTBOLT, 2_000, t0); @@ -950,8 +993,10 @@ mod tests { "and with no channel there is nothing to trim" ); - let mut off = PressRules::defaults_for_tests(); - off.channel_latency_reduction_pct = 0; + let off = PressRules { + channel_latency_reduction_pct: 0, + ..Default::default() + }; assert_eq!( off.channel_guard_until(&channel, Some(100), t0), Some(t0 + Duration::from_secs(2)), @@ -962,7 +1007,7 @@ mod tests { /// The retry set: two timing codes and nothing else, whatever the row says. #[test] fn the_retry_set_is_the_two_codes_an_early_guard_can_cause() { - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); assert!(r.retry_reason(0x3c), "not ready"); assert!(r.retry_reason(0x61), "another action is in progress"); for refusal in [0x4d, 0x0a, 0x13, 0x2e, 0x39, 0x78, 0x17, 0x00] { @@ -972,8 +1017,10 @@ mod tests { is a packet a second that never succeeds" ); } - let mut off = PressRules::defaults_for_tests(); - off.retry_server_rejected = false; + let off = PressRules { + retry_server_rejected: false, + ..Default::default() + }; assert!(!off.retry_reason(0x3c)); } @@ -985,12 +1032,14 @@ mod tests { category, ..Default::default() }; - let off = PressRules::defaults_for_tests(); + let off = PressRules::default(); assert!(off.non_gcd_may_replace(Some(&cat(1)), Some(&cat(2)))); assert!(off.non_gcd_may_replace(None, None)); - let mut on = PressRules::defaults_for_tests(); - on.replace_matching_non_gcd_category = true; + let on = PressRules { + replace_matching_non_gcd_category: true, + ..Default::default() + }; assert!(on.non_gcd_may_replace(Some(&cat(7)), Some(&cat(7)))); assert!(!on.non_gcd_may_replace(Some(&cat(7)), Some(&cat(8)))); assert!( @@ -1007,7 +1056,7 @@ mod tests { /// two presses. #[test] fn the_buffer_forks_on_whether_the_spell_costs_a_global_cooldown() { - let r = PressRules::defaults_for_tests(); + let r = PressRules::default(); assert_eq!(r.buffer_for(Some(&instant())), 55); assert_eq!( r.buffer_for(Some(&SpellDisplay::default())), @@ -1045,6 +1094,64 @@ mod tests { ); } + /// Every field of [`PressRules::default`] is the value `cvars.rs` registers for its row. + /// + /// This is the gate on the defect that made the whole press queue inert in play: the registry + /// announces a `CvarChanged` only when a value **moves**, and at boot only the rows + /// `config.toml` overrides move — the file holds nothing else, by design ("CVar values that + /// moved off their defaults"). So an untouched row never reaches [`on_cvar`] and `Default` is + /// the live configuration. A `#[derive(Default)]` therefore shipped every toggle false and + /// every window 0, and no test saw it, because each test world built the resource by hand. + #[test] + fn the_default_is_the_registry() { + let d = PressRules::default(); + let registered = |name: &str| -> &'static str { + crate::cvars::REGISTERED + .iter() + .find(|r| r.name.eq_ignore_ascii_case(name)) + .unwrap_or_else(|| panic!("{name} is not a registered CVar")) + .default + }; + let flag = |name: &str| registered(name) != "0"; + let num = |name: &str| { + registered(name) + .parse::() + .unwrap_or_else(|e| panic!("{name}'s default is not a number: {e}")) + }; + assert_eq!(d.prevent_mounting_buff_capped, flag(CVAR_PREVENT_MOUNTING)); + assert_eq!(d.queue_cast_time, flag(CVAR_QUEUE_CAST_TIME)); + assert_eq!(d.queue_instant, flag(CVAR_QUEUE_INSTANT)); + assert_eq!(d.queue_channeling, flag(CVAR_QUEUE_CHANNELING)); + assert_eq!(d.queue_targeting, flag(CVAR_QUEUE_TARGETING)); + assert_eq!(d.queue_on_swing, flag(CVAR_QUEUE_ON_SWING)); + assert_eq!(d.window_spell_ms, num(CVAR_WINDOW_SPELL)); + assert_eq!(d.window_channel_ms, num(CVAR_WINDOW_CHANNEL)); + assert_eq!(d.window_cooldown_ms, num(CVAR_WINDOW_COOLDOWN)); + assert_eq!(d.window_targeting_ms, num(CVAR_WINDOW_TARGETING)); + assert_eq!(d.buffer_ms, num(CVAR_BUFFER)); + assert_eq!(d.buffer_non_gcd_ms, num(CVAR_BUFFER_NON_GCD)); + assert_eq!(d.spam_protection, flag(CVAR_SPAM_PROTECTION)); + assert_eq!( + d.interrupt_channels_outside_window, + flag(CVAR_INTERRUPT_OUTSIDE_WINDOW) + ); + assert_eq!( + d.replace_matching_non_gcd_category, + flag(CVAR_REPLACE_MATCHING_NON_GCD) + ); + assert_eq!(d.retry_server_rejected, flag(CVAR_RETRY_REJECTED)); + assert_eq!( + d.channel_latency_reduction_pct, + num(CVAR_CHANNEL_LATENCY_REDUCTION) + ); + // And the half a per-field list cannot state: the queue is **on** out of the box, which is + // what upstream ships and what makes the rows above worth having. + assert!( + d.queue_instant && d.queue_cast_time && d.buffer_ms > 0 && d.window_spell_ms > 0, + "a player who touched no CVar must get nampower's own queue, not an inert one" + ); + } + /// Against the real `Spell.dbc`: [`SPELL_AURA_MOUNTED`] is the number this realm's own mount /// spells carry, not one taken on trust. Skips without client data. /// diff --git a/crates/benilla-app/src/spell/queue.rs b/crates/benilla-app/src/spell/queue.rs index 5db0337e..bf07a9e8 100644 --- a/crates/benilla-app/src/spell/queue.rs +++ b/crates/benilla-app/src/spell/queue.rs @@ -115,12 +115,45 @@ struct Script { expires: Instant, } +/// What the press queue did in the reporting period, for the one line it prints at `info`. +/// +/// **Every other line this half of the client writes is `debug!`, which the default filter drops** +/// — so without this a whole session says nothing about whether a press was held, popped, dropped +/// or refused, and the only evidence left is the player's own combat log. The period is long and +/// the line is skipped when nothing moved, so an idle session stays quiet. +#[derive(Default)] +pub(crate) struct Tally { + /// Presses held by [`super::np_press::PressRules::admit`]. + pub(crate) held: u32, + /// Held presses that reached the wire. + pub(crate) sent: u32, + /// Held presses that gave up: the window ran out, or the spell was cold with + /// `NP_QueueSpellsOnCooldown` off. The failure mode a player cannot describe. + pub(crate) dropped: u32, + /// Casts re-sent after a server refusal (`NP_RetryServerRejectedSpells`). + pub(crate) retried: u32, + /// Presses the rules declined to hold while something still guarded — each one is an error + /// line the player read. A high count beside a low `held` is the queue not doing its job. + pub(crate) fell_through: u32, + /// Presses that ended a channel instead (`NP_InterruptChannelsOutsideQueueWindow`). + pub(crate) interrupted: u32, + /// When the period began; `None` until the first event. + since: Option, +} + +impl Tally { + fn moved(&self) -> bool { + self.held | self.sent | self.dropped | self.retried | self.fell_through | self.interrupted + != 0 + } +} + /// The queue: one slot per [`Kind`], plus the scripts. /// /// `pub(crate)` fields are avoided on purpose — every mutation goes through [`Self::queue`] or /// [`Self::pop`], so the `SPELL_QUEUE_EVENT` rows cannot be forgotten by a caller that writes a /// slot directly. -#[derive(Resource, Default)] +#[derive(Resource)] pub(crate) struct SpellQueue { on_swing: Option, non_gcd: Option, @@ -133,7 +166,8 @@ pub(crate) struct SpellQueue { /// gate working as intended: this module really is gameplay state and not a feed.) events: Vec<(i64, u32)>, /// `NP_SpellQueueWindowMs`, the one window this half of the queue has a use for: how long an - /// entry is held before it gives up. Seeded by the `CvarChanged` observer. + /// entry is held before it gives up. [`Default`] carries the registered 500, because a row + /// the player never moved never reaches [`on_cvar`] — see [`super::np_press::PressRules`]. window_ms: u32, /// `NP_QueueSpellsOnCooldown`: whether an entry may sit in the queue while the spell itself is /// on cooldown, or is dropped on the spot. @@ -142,22 +176,31 @@ pub(crate) struct SpellQueue { stop_channel: bool, /// The spell a server refusal has already been retried for. See [`Self::queue_retry`]. retried: Option, + /// The period's counters, reported by [`Self::take_report`]. + tally: Tally, +} + +/// `NP_SpellQueueWindowMs` 500 and `NP_QueueSpellsOnCooldown` 1 — the values `cvars.rs` registers, +/// which is what a player who touched neither row runs. A derived `Default` gave a window of 0, +/// and an entry whose window is 0 expires on the frame it was queued. +impl Default for SpellQueue { + fn default() -> Self { + Self { + on_swing: None, + non_gcd: None, + normal: None, + scripts: Vec::new(), + events: Vec::new(), + window_ms: 500, + allow_on_cooldown: true, + stop_channel: false, + retried: None, + tally: Tally::default(), + } + } } impl SpellQueue { - /// The resource as `cvars.rs` seeds it: `NP_SpellQueueWindowMs` 500 and - /// `NP_QueueSpellsOnCooldown` 1. Test-only, so a test world reads the behaviour a player who - /// touched nothing gets rather than `Default`'s all-zeroes, which is a configuration nobody - /// runs. - #[cfg(test)] - pub(crate) fn defaults_for_tests() -> Self { - Self { - window_ms: 500, - allow_on_cooldown: true, - ..Default::default() - } - } - /// Put `spell_id` in the slot its `kind` implies, replacing whatever was there. /// /// **Replacing, not refusing**, which is upstream's own behaviour — its log line is @@ -223,6 +266,8 @@ impl SpellQueue { return false; } self.retried = Some(spell_id); + self.tally.since.get_or_insert(now); + self.tally.retried += 1; let not_before = now + Duration::from_millis(u64::from(delay_ms)); *self.slot_mut(kind) = Some(Slot { spell_id, @@ -234,6 +279,35 @@ impl SpellQueue { true } + /// The counter pokes. Each is one line at its site, so a new path that holds or drops a press + /// cannot forget to be countable — see [`Tally`] for why counting matters at all. + pub(crate) fn note_held(&mut self, now: Instant) { + self.tally.since.get_or_insert(now); + self.tally.held += 1; + } + + pub(crate) fn note_fell_through(&mut self, now: Instant) { + self.tally.since.get_or_insert(now); + self.tally.fell_through += 1; + } + + pub(crate) fn note_interrupted(&mut self, now: Instant) { + self.tally.since.get_or_insert(now); + self.tally.interrupted += 1; + } + + /// The period's line, or `None` while it is too young or empty. Resets on the way out. + /// + /// 60 s, because the question it answers ("is the queue working at all") does not need a + /// finer grain, and a line a minute is a size a session log can carry. + pub(crate) fn take_report(&mut self, now: Instant) -> Option { + let since = self.tally.since?; + if !self.tally.moved() || now.duration_since(since) < Duration::from_secs(60) { + return None; + } + Some(std::mem::take(&mut self.tally)) + } + /// Forget the retry memo: a cast the server accepted means the next refusal is a new one. pub(crate) fn clear_retry(&mut self) { self.retried = None; @@ -265,6 +339,19 @@ impl SpellQueue { return None; } let spell_id = self.slot_mut(kind).take()?.spell_id; + self.tally.since.get_or_insert(now); + self.tally.sent += 1; + self.events.push((kind.popped_code(), spell_id)); + Some(spell_id) + } + + /// Take `kind`'s slot and count it as given up rather than sent — the queue's own decision to + /// abandon an entry, as against [`Self::expire`]'s window running out. The `*_POPPED` row still + /// goes out, because an addon tracking the slot has to see it empty either way. + pub(crate) fn discard(&mut self, kind: Kind, now: Instant) -> Option { + let spell_id = self.slot_mut(kind).take()?.spell_id; + self.tally.since.get_or_insert(now); + self.tally.dropped += 1; self.events.push((kind.popped_code(), spell_id)); Some(spell_id) } @@ -306,6 +393,8 @@ impl SpellQueue { if slot.expired(now) { let dropped = self.slot_mut(kind).take(); if let Some(s) = dropped { + self.tally.since.get_or_insert(now); + self.tally.dropped += 1; debug!( "spell-queue: dropping {:?} spell {} — nothing popped it inside the window", kind, s.spell_id @@ -396,6 +485,34 @@ mod tests { } } + /// The period line counts what happened and holds its tongue until the period is up — and + /// `Default` is the registry, which is the bug this file shipped with. + #[test] + fn the_tally_reports_once_a_period_and_only_when_something_moved() { + let mut q = SpellQueue::default(); + assert_eq!(q.window_ms, 500, "the registered NP_SpellQueueWindowMs"); + assert!( + q.allow_on_cooldown, + "the registered NP_QueueSpellsOnCooldown" + ); + + let t0 = Instant::now(); + assert!(q.take_report(t0).is_none(), "nothing has happened yet"); + q.note_held(t0); + q.note_fell_through(t0); + assert!( + q.take_report(t0).is_none(), + "the period is a minute long: two events in the first millisecond print nothing" + ); + let later = t0 + Duration::from_secs(61); + let r = q.take_report(later).expect("the period is up and it moved"); + assert_eq!((r.held, r.fell_through), (1, 1)); + assert!( + q.take_report(later + Duration::from_secs(61)).is_none(), + "the counters reset, so a quiet minute stays out of the log" + ); + } + /// The three kinds, off the same tests the send path makes. `0x404` is the on-next-swing pair. #[test] fn a_spells_kind_is_its_own_dbc_row() { diff --git a/crates/benilla-app/src/ui_spellbook.rs b/crates/benilla-app/src/ui_spellbook.rs index 95bb9a0f..9f771c1a 100644 --- a/crates/benilla-app/src/ui_spellbook.rs +++ b/crates/benilla-app/src/ui_spellbook.rs @@ -656,7 +656,7 @@ fn drain_spell_queue( continue; } debug!("spell-queue: dropping {spell_id} — on cooldown, and NP_QueueSpellsOnCooldown is off"); - ladder.queue.pop(kind, now); + ladder.queue.discard(kind, now); continue; } let Some(spell_id) = ladder.queue.pop(kind, now) else { @@ -672,6 +672,30 @@ fn drain_spell_queue( ladder.send_now(spell_id, &targeting.context(), CastCommit::Spell); } + // The period line, at `info` — the only one this half of the client writes above `debug`, and + // the reason is [`crate::spell::queue::Tally`]: without it a whole session cannot say whether + // a press was ever held. The knobs ride along because a line of zeroes is its own diagnosis: + // that is what a resource whose `Default` was derived looks like in play, which is exactly how + // the queue came to do nothing on the day it was committed. + if let Some(t) = ladder.queue.take_report(now) { + info!( + "np-press: {} held, {} sent, {} dropped, {} retried, {} fell through, {} channels cut \ + — windows {}/{}/{}/{} ms, buffers {}/{} ms", + t.held, + t.sent, + t.dropped, + t.retried, + t.fell_through, + t.interrupted, + ladder.np.window_spell_ms(), + ladder.np.window_channel_ms(), + ladder.np.window_cooldown_ms(), + ladder.np.window_targeting_ms(), + ladder.np.buffer_ms(), + ladder.np.buffer_non_gcd_ms(), + ); + } + // The scripts, once every **spell** slot is empty — "after queued spells", which is // `SuperCleveRoidMacros`' own words for what it uses `QueueScript` for. if ladder.queue.no_spells_waiting() { @@ -834,8 +858,8 @@ mod tests { .init_resource::() .init_resource::() .init_resource::() - .insert_resource(crate::spell::np_press::PressRules::defaults_for_tests()) - .insert_resource(SpellQueue::defaults_for_tests()) + .insert_resource(crate::spell::np_press::PressRules::default()) + .insert_resource(SpellQueue::default()) .add_message::(); // Two ordinary cast-time spells, so the press lands in the Normal slot. let mut spells = crate::ui_action::Spells::empty_for_tests(); @@ -933,6 +957,152 @@ mod tests { assert!(rx.try_recv().is_err(), "exactly one packet for one press"); } + /// The same cycle with the **global cooldown** as the only guard, which is what a class with + /// no cast bar presses into all day — and the half the test above cannot see, because it arms + /// `PendingCast` by hand and so never starts a GCD at all. + /// + /// Two presses of one instant, 1.5 s apart in play: the second is held while the global + /// cooldown runs and sent when it ends. A `send` that fell through here would reach the + /// server during its own global cooldown and come back "Not yet recovered" — an error line + /// for a press the queue exists to absorb. + #[test] + fn a_press_made_during_the_global_cooldown_is_held_and_sent_when_it_ends() { + use crate::spell::queue::{Kind, SpellQueue}; + use benilla_protocol::messages::ObjectType; + use benilla_protocol::ObjectFields; + use bevy::ecs::system::RunSystemOnce; + use std::time::{Duration, Instant}; + + /// Sunder Armor rank 1, whose row on this realm is a global cooldown and nothing else + /// (`rec=0 cat=0 catrec=0 gcdcat=133 gcd=1500`, measured off its own `Spell.dbc`). The + /// GCD here is 120 ms so the test can wait it out. + const SUNDER: u32 = 7386; + const GCD_MS: u32 = 120; + + let (tx, rx) = crossbeam_channel::unbounded(); + let mut app = App::new(); + app.insert_resource(crate::net::NetCommands(tx)) + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .init_resource::() + .insert_resource(crate::spell::np_press::PressRules::default()) + .insert_resource(SpellQueue::default()) + .add_message::(); + let mut spells = crate::ui_action::Spells::empty_for_tests(); + spells.catalog = benilla_formats::SpellCatalog::from_displays(HashMap::from([( + SUNDER, + SpellDisplay { + start_recovery_ms: GCD_MS, + start_recovery_category: 133, + ..Default::default() + }, + )])); + app.insert_resource(spells); + app.world_mut().spawn(( + crate::net::SelfPlayer, + crate::net::ObjectStore( + ObjectFields::from_pairs(&[(22, 100), (28, 100)]).into_created(ObjectType::Player), + ), + Transform::default(), + )); + let script = benilla_ui::script::UiScript::new().expect("a VM"); + app.insert_non_send_resource(script); + + let press = |app: &mut App| { + app.world_mut() + .run_system_once( + move |mut ladder: crate::spell::CastLadder, t: cast_target::CastTargeting| { + ladder.send(SUNDER, &t.context(), CastCommit::Spell); + }, + ) + .expect("the ladder runs as a one-shot system"); + }; + + // The first press: nothing guards, so it goes out — and the commit starts the GCD, the + // way a real cast does (`start_gcd` at the foot of the send). + let t0 = Instant::now(); + press(&mut app); + assert!( + matches!( + rx.try_recv(), + Ok(crate::net::ClientCommand::CastSpell { spell_id, .. }) if spell_id == SUNDER + ), + "the first press is an ordinary cast" + ); + assert!( + app.world() + .resource::() + .gcd(t0) + .is_some(), + "the commit armed the global cooldown — without this the test proves nothing" + ); + + // The second press, with the GCD running and the cast's own 55 ms guard long gone. The + // reference refuses this with 0x3c; nampower holds it. + std::thread::sleep(Duration::from_millis(60)); + press(&mut app); + assert!(rx.try_recv().is_err(), "nothing on the wire: it was held"); + assert_eq!( + app.world().resource::().peek(Kind::Normal), + Some(SUNDER), + "a press made during the global cooldown belongs in the slot, not on the wire" + ); + assert!( + app.world() + .resource::() + .0 + .is_empty(), + "and it raises no error line" + ); + + // A drain while the GCD still runs leaves it there. + app.world_mut() + .run_system_once(drain_spell_casts) + .expect("the drain runs as a one-shot system"); + assert!(rx.try_recv().is_err(), "the GCD still guards"); + assert_eq!( + app.world().resource::().peek(Kind::Normal), + Some(SUNDER), + "and the entry is neither sent nor dropped while it waits" + ); + + // The GCD ends; the next drain sends it, once. + std::thread::sleep(Duration::from_millis(GCD_MS as u64)); + app.world_mut() + .run_system_once(drain_spell_casts) + .expect("the drain runs as a one-shot system"); + assert!( + matches!( + rx.try_recv(), + Ok(crate::net::ClientCommand::CastSpell { spell_id, .. }) if spell_id == SUNDER + ), + "the held press reached the wire when the global cooldown ended" + ); + assert_eq!( + app.world().resource::().peek(Kind::Normal), + None + ); + app.world_mut() + .run_system_once(drain_spell_casts) + .expect("the drain runs as a one-shot system"); + assert!(rx.try_recv().is_err(), "exactly one packet for one press"); + } + #[test] fn leading_number_scans_the_first_digit_run() { assert_eq!(leading_number("Rank 1"), 1); diff --git a/docs/ADDON_COMPAT.md b/docs/ADDON_COMPAT.md index 0cbd757a..c732d9f7 100644 --- a/docs/ADDON_COMPAT.md +++ b/docs/ADDON_COMPAT.md @@ -976,6 +976,21 @@ were the plain cast, which was the honest mapping at the time and is no longer t same slot an explicit `QueueSpellByName` would use, and the drain sends it the moment the guard clears. No packet, no global cooldown, no error line while it waits. +**It shipped doing nothing, and the reason is worth writing down here rather than only in the +code.** `cvars.rs` announces a `CvarChanged` only when a value *moves*, and `config.toml` holds only +the rows that left their defaults — so a row the player never touched never reaches an `on_cvar` +observer, and the resource's own `Default` is the live configuration for the whole session. Both +`PressRules` and `SpellQueue` derived `Default`, which meant every toggle false, every window 0 and +every buffer 0 on the day this landed: the queue held nothing, and `SpellQueue`'s zero window +expired each explicit entry on the frame it was queued. Fourteen of the sixteen rows have a +non-zero registered default. Both now hand-write `Default` with the registered values, welded by +`np_press.rs::the_default_is_the_registry`, and a sweep of the other nine CVar-cached resources +found no further victims. What caught it was the player's own `WoWCombatLog.txt` — 147 +`Sunder Armor: Not yet recovered` against 163 landed Sunders, in bursts a fifth of a second apart — +because every line this module writes is `debug!` and the default filter is INFO. So the drain now +prints one `info!` a minute when something moved, carrying held/sent/dropped/retried/fell-through +**and the live windows and buffers**: a line of zeroes diagnoses this class of fault by itself. + **Where the rung sits, and the one deviation that comes of it.** Five rungs stay above it — the profession opener, the auto-repeat re-press, the dead caster, the targeting cursor's clear and the on-swing re-press — because each is what the press *means* whatever is in flight, and holding them