addons: an on-demand load says what it loaded

The startup walk names every addon it loads; `LoadAddOn` named none. So when
the client froze on 10-19 while learning recipes, the session log could not
say whether the trainer window was even open — and `Blizzard_TrainerUI` is
LoadOnDemand, so that was the whole question.

`benilla-ui` has no logger, so the line travels the way its errors and
warnings already do: a `notices` channel on the model, drained to `info!`
beside them in the same pass. Silent for a redundant load, because the stock
`*_LoadUI` glue calls `LoadAddOn` on every open and a line per call would
bury the one that did the work. A refusal carries the reference's own reason
token, and a name that is not installed says so.

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

crates/benilla-app/src/ui_script/addons.rs

@@ -2366,6 +2366,72 @@ mod tests {
         let _ = std::fs::remove_dir_all(home.parent().unwrap());
     }
 
+    /// An on-demand load names itself on the host's notice channel, once. The startup walk logs
+    /// every addon it loads; this path logged none, so a session log could not say which window
+    /// was open when the client stalled — and the stock `*_LoadUI` glue calls `LoadAddOn` on every
+    /// open, so a line per call would have buried the one that did the work.
+    #[test]
+    fn an_on_demand_load_names_itself_once_and_a_refusal_names_its_reason() {
+        let _l = crate::local_state::test_env::ENV_LOCK
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner);
+        let _c = crate::local_state::test_env::EnvGuard::unset("WOW_CAPTURE");
+        let (home, _h) = hermetic_root("notices");
+        write_addon(
+            &home,
+            "Window",
+            "## Interface: 11200\n## LoadOnDemand: 1\nran.lua\n",
+            &[("ran.lua", "WindowRan = true")],
+        );
+        write_addon(
+            &home,
+            "Off",
+            "## Interface: 11200\n## LoadOnDemand: 1\n",
+            &[],
+        );
+        std::fs::create_dir_all(home.join("addons")).unwrap();
+        std::fs::write(home.join("addons/Realm-Char.txt"), "Off: disabled\n").unwrap();
+
+        let mut script = UiScript::new().unwrap();
+        let id = ("Realm".to_string(), "Char".to_string());
+        let _ = load_third_party(&mut script, Some(&id), &[], true);
+        // The startup walk's own notices, out of the way: what follows is the demand path alone.
+        let _ = script.take_notices();
+
+        script.run("LoadAddOn('Window')").unwrap();
+        assert_eq!(
+            script.take_notices(),
+            vec!["LoadAddOn: Window loaded on demand".to_string()],
+            "the load that ran the files names the addon"
+        );
+        assert_eq!(
+            script.eval::<bool>("return WindowRan == true").ok(),
+            Some(true),
+            "and it really loaded"
+        );
+
+        script.run("LoadAddOn('Window')").unwrap();
+        assert!(
+            script.take_notices().is_empty(),
+            "a redundant load is a no-op and says nothing"
+        );
+
+        script.run("LoadAddOn('Off')").unwrap();
+        assert_eq!(
+            script.take_notices(),
+            vec!["LoadAddOn: Off refused (DISABLED)".to_string()],
+            "a refusal carries the reference's own reason token"
+        );
+
+        script.run("LoadAddOn('NoSuchAddon')").unwrap();
+        assert_eq!(
+            script.take_notices(),
+            vec!["LoadAddOn: no addon named \"NoSuchAddon\" (MISSING)".to_string()],
+            "a name that is not installed says so"
+        );
+        let _ = std::fs::remove_dir_all(home.parent().unwrap());
+    }
+
     /// `AddOn_CanLoad` check 3 is `0x51e470(name, character, useDefault = 1)`. `Contested` is the
     /// control: the roster disagrees about it, so the newcomer gets its `## DefaultState`.
     #[test]

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

@@ -567,6 +567,9 @@ pub(super) fn tick_script(
     for w in script.take_warnings() {
         warn!("ui_script: {w}");
     }
+    for n in script.take_notices() {
+        info!("ui_script: {n}");
+    }
 
     // ── The handover ────────────────────────────────────────────────────────────────────────
     *pass = super::UiPassState {

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

@@ -359,23 +359,47 @@ pub(super) fn install(lua: &Lua) -> mlua::Result<()> {
     g.set(
         "LoadAddOn",
         lua.create_function(|lua, key: Value| {
-            let index = {
+            let (index, asked) = {
                 let model = lua.app_data_ref::<Model>().expect("model");
                 let key = addon_key(lua, &model, &key, USAGE_LOAD)?;
-                row_of(&model, &key)
+                (row_of(&model, &key), key)
             };
             let Some(i) = index else {
+                // Only a name reaches here: an index key is bounds-checked into a real row by
+                // `addon_key`, and `row_of` answers every row.
+                let AddonKey::Name(asked) = asked else {
+                    unreachable!("an index key names a row")
+                };
+                note(
+                    lua,
+                    format!("LoadAddOn: no addon named {asked:?} (MISSING)"),
+                );
                 return Ok(MultiValue::from_vec(vec![
                     Value::Nil,
                     lua_str(lua, "MISSING")?,
                 ]));
             };
+            // Read before the load, so the notice below names only the loads that did something:
+            // the stock `*_LoadUI` glue calls this on every open, and a redundant load succeeds
+            // silently (`0x51f2d6`), which a log line per open would bury.
+            let (name, already) = {
+                let model = lua.app_data_ref::<Model>().expect("model");
+                (model.addons[i].name.clone(), model.addons[i].loaded)
+            };
             match load_addon(lua, i) {
-                Ok(()) => Ok(MultiValue::from_vec(vec![Value::Integer(1), Value::Nil])),
-                Err(reason) => Ok(MultiValue::from_vec(vec![
-                    Value::Nil,
-                    lua_str(lua, &reason)?,
-                ])),
+                Ok(()) => {
+                    if !already {
+                        note(lua, format!("LoadAddOn: {name} loaded on demand"));
+                    }
+                    Ok(MultiValue::from_vec(vec![Value::Integer(1), Value::Nil]))
+                }
+                Err(reason) => {
+                    note(lua, format!("LoadAddOn: {name} refused ({reason})"));
+                    Ok(MultiValue::from_vec(vec![
+                        Value::Nil,
+                        lua_str(lua, &reason)?,
+                    ]))
+                }
             }
         })?,
     )?;
@@ -599,6 +623,16 @@ fn load_failure(lua: &Lua, msg: &str) {
         .warn_host_only(msg);
 }
 
+/// Put a line on the host's `info!` channel. An on-demand load is neither a fault nor noise:
+/// the startup walk logs every addon it loads and this path logged none, so a session log could
+/// not say whether, say, the trainer window was open when the client stalled.
+fn note(lua: &Lua, msg: String) {
+    lua.app_data_mut::<Model>()
+        .expect("model")
+        .notices
+        .push(msg);
+}
+
 /// Read `root/rel`, refusing a path that leaves `root`, lexically before any filesystem call;
 /// `join_ref` has already resolved the path, so an escape shows as a leading `..`.
 fn read_under(root: &std::path::Path, rel: &str) -> Option<Vec<u8>> {

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

@@ -1387,6 +1387,11 @@ impl UiScript {
         std::mem::take(&mut self.model_mut().warnings)
     }
 
+    /// Drain the host notices, for the host to log at `info!`.
+    pub fn take_notices(&mut self) -> Vec<String> {
+        std::mem::take(&mut self.model_mut().notices)
+    }
+
     /// 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.

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

@@ -488,6 +488,10 @@ pub(crate) struct Model {
     pub(crate) diagnostics: super::diagnostics::DiagnosticLog,
     /// Non-fatal warnings for the host, such as a dropped `inherits=` template.
     pub(crate) warnings: Vec<String>,
+    /// Things the host should log at `info!` because they are neither a fault nor noise — an
+    /// on-demand `LoadAddOn` is the first: the startup walk names every addon it loads, this path
+    /// named none, so a session log could not say which window was open when it stalled.
+    pub(crate) notices: Vec<String>,
     /// The screen-root rect (`[bottom, left, top, right]`), the anchor base for top-level frames.
     pub(crate) screen: Rect,
 
@@ -1649,6 +1653,7 @@ impl Model {
             pending_error_dispatch: Vec::new(),
             diagnostics: Default::default(),
             warnings: Vec::new(),
+            notices: Vec::new(),
             // 1024x768 until the host calls `set_screen_size`; y-up `[bottom, left, top, right]`.
             screen: Rect::new(0.0, 0.0, 768.0, 1024.0),
             units_by_lower: HashMap::new(),