fix(drill): staging 26341433's swap fields; a failed group no longer ends the harness (#20)

The staging drill's run 47 failed on Rust staging 26341433: - Rust added BasePlayer.timeSinceAiming, BaseEntity.ServerPreProcessed and BaseNetworkable.ignoreNetworkLod to the swap's field list (D232): 55 -> 58. On edge now; main at the forced wipe of 2026-11-05. - Harness 0.7.4: place.set.each was refused and the refusal was thrown away; place.spawned failed; reading each[0] of an empty list then killed the coroutine, so the drill waited 45 minutes for a run that had stopped after 10. Place puts its spots on the navmesh, the set checks carry the refusal, a failed place.spawned ends the group, and any group that throws is a <group>.exception FAIL line and the run goes on. - drill.js: rust-staging boots from empty Kits and RunicNPC data, so the write-once example kits match this Rust (s6.examples.fullCondition); the wait ends after 5 minutes without a new harness line; latest.log's tail goes into the issue when the harness did not finish. drill.test.js covers the stall logic. Refs #20, #21 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01E14m6SuuY6i1vASFeGDBeY
2026-11-01 01:30:10 -06:00
parent 27bafedb03
commit bad19a668d
5 changed files with 167 additions and 28 deletions
--- a/README.md
+++ b/README.md
@@ -98,7 +98,7 @@ The API version moves when a call or a raised hook changes shape, not on every r
 ## After a Rust update: the swap's field list

 Our NPC is Rust's scientist with two components swapped, and the swap copies a fixed list of fields (D232),
-generated from Rust's unmodified assembly. `rnpc.status` reports it as `swap fields: npc=55/55 brain=32/32
+generated from Rust's unmodified assembly. `rnpc.status` reports it as `swap fields: npc=58/58 brain=32/32
 missing=- added=-`. On Carbon, where the assembly is unmodified, `added` names any field Rust has added since
 the list was made. To regenerate it:

@@ -121,7 +121,7 @@ shows it, so the drill's live half and `rnpc.status` are what catch it.

 | Rust type | What RunicNPC depends on | Where (`plugin/RunicNPC.cs`) | Caught by |
 |---|---|---|---|
-| `ScientistNPC` (prefabs `scientistnpc_*`) | Subclassed by `RunicNpcPlayer`; the swap replaces the prefab's component before spawn and copies `SwapNpcFields` (55 fields up its chain to `BaseNetworkable`) | `#region The swap`, `CreateNpc` | compile; field list |
+| `ScientistNPC` (prefabs `scientistnpc_*`) | Subclassed by `RunicNpcPlayer`; the swap replaces the prefab's component before spawn and copies `SwapNpcFields` (58 fields up its chain to `BaseNetworkable`) | `#region The swap`, `CreateNpc` | compile; field list |
 | `ScientistBrain` | Subclassed by `RunicNpcBrain`; the swap copies `SwapBrainFields` (32 fields of `BaseAIBrain`) | `#region The swap` | compile; field list |
 | `ScientistNPC` / `HumanNPC` virtuals | `displayName`, `AttackerInfo(PlayerLifeStory.DeathInfo)`, `ShotTest(float)`, `TriggerDown()`, `Hurt(HitInfo)`, `OnDied(HitInfo)` overridden | `RunicNpcPlayer` | compile |
 | `IAIAttack`, `IAISenses` | Re-implemented on `RunicNpcPlayer`: `IsTargetInRange`, `EngagementRange`, `GetBestTarget`, `AttackTick`, `IsTarget`, `IsThreat`, `IsFriendly`. Rust's `HumanNPC.IsTarget` is not virtual, which is why | `RunicNpcPlayer` | compile; a changed meaning only at run time |
@@ -153,8 +153,10 @@ the week. A run by hand always goes ahead.
  plugin against them.
 - **Live, once per build** (`tools/drill/drill.js live`): the `rust-staging` server (Oxide, a 3500 map)
  installs the same pair at start (`tools/drill/rig-start.sh`), loads RunicNPC, Kits and
-  `tools/RunicNpcTest.cs`, and runs `rnt.run all`. When both 6000-map rigs are running, `rust-carbon` is
-  stopped for it and started again.
+  `tools/RunicNpcTest.cs`, and runs `rnt.run all`. It starts the server from empty Kits and RunicNPC data
+  (their files are deleted first, so the example kits are written afresh) and gives up on the harness after
+  5 minutes with no new output (45 minutes at most), putting the tail of the server's log in the issue. When
+  both 6000-map rigs are running, `rust-carbon` is stopped for it and started again.
 - **Report:** anything that fails or differs opens one issue for that build, labelled `staging-drill`.
  The last build checked is kept on the `drill` branch.

--- a/plugin/RunicNPC.cs
+++ b/plugin/RunicNPC.cs
@@ -947,6 +947,7 @@ namespace Oxide.Plugins
            "BasePlayer.debugCommandedNpcs",
            "BasePlayer.GestureViewModel",
            "BasePlayer.lastPlayerVisibility",
+            "BasePlayer.timeSinceAiming",
            "BasePlayer.eyeHistory",
            "BasePlayer.tickHistory",
            "BasePlayer.fallDamageEffect",
@@ -974,12 +975,14 @@ namespace Oxide.Plugins
            "BaseEntity.model",
            "BaseEntity.flags",
            "BaseEntity.HasBrain",
+            "BaseEntity.ServerPreProcessed",
            "BaseNetworkable.postNetworkUpdateComponents",
            "BaseNetworkable.prefabID",
            "BaseNetworkable.globalBroadcast",
            "BaseNetworkable.globalNetworkBehavior",
            "BaseNetworkable.globalBuildingBlock",
            "BaseNetworkable.networkRange",
+            "BaseNetworkable.ignoreNetworkLod",
        };
        private static readonly string[] SwapBrainFields =
        {
--- a/tools/RunicNpcTest.cs
+++ b/tools/RunicNpcTest.cs
@@ -45,7 +45,7 @@ namespace Oxide.Plugins
    ///     a made-up user id (11400000001 and up), so <c>IsNpc</c> is false. They take no damage.
    ///     </para>
    /// </summary>
-    [Info("RunicNpcTest", "Runic Gateway", "0.7.3")]
+    [Info("RunicNpcTest", "Runic Gateway", "0.7.4")]
    [Description("RunicNPC stage 2 to 7 tests, the stage 6 spike and stage 9's cost check. A developer tool: never ship it.")]
    internal class RunicNpcTest : RustPlugin
    {
@@ -753,7 +753,25 @@ namespace Oxide.Plugins
                    continue;
                }

-                while (inner.MoveNext()) yield return inner.Current;
+                // A group that throws is a FAIL line, not the end of the run: yield cannot sit inside a try, so
+                // each step is taken inside one and the value is yielded outside it.
+                while (true)
+                {
+                    object step;
+                    try
+                    {
+                        if (!inner.MoveNext()) break;
+                        step = inner.Current;
+                    }
+                    catch (Exception e)
+                    {
+                        Check($"{g}.exception", false, $"{e.GetType().Name}: {e.Message} at {(e.StackTrace ?? "").Split('\n').FirstOrDefault()?.Trim()}");
+                        break;
+                    }
+
+                    yield return step;
+                }
+
                Api<int>("RunicNpc_DespawnOwner", Owner);
                ClearWorld();
                yield return new WaitForSeconds(1f);
@@ -1095,16 +1113,27 @@ namespace Oxide.Plugins

        private IEnumerator Place(Vector3 field)
        {
-            Vector3 a = field + new Vector3(-40, 0, 0);
-            Vector3 b = field + new Vector3(-40, 0, 30);
-            StandIn(field + new Vector3(-40, 0, 110), 8);
-            Check("place.set.each", Api<string>("RunicNpc_SetPlacement", "t_each", Placement("t_each", a, 3, 20f, "each")) == null, "");
-            Check("place.set.group", Api<string>("RunicNpc_SetPlacement", "t_group", Placement("t_roam", b, 3, 20f, "group")) == null, "");
+            // A roamer's spot must be on the navmesh when it is set (D219), so both spots are put there.
+            Vector3 a = OnMesh(field + new Vector3(-40, 0, 0));
+            Vector3 b = OnMesh(field + new Vector3(-40, 0, 30));
+            StandIn(OnMesh(field + new Vector3(-40, 0, 110)), 8);
+            string eachRefusal = Api<string>("RunicNpc_SetPlacement", "t_each", Placement("t_each", a, 3, 20f, "each"));
+            Check("place.set.each", eachRefusal == null, eachRefusal ?? "");
+            string groupRefusal = Api<string>("RunicNpc_SetPlacement", "t_group", Placement("t_roam", b, 3, 20f, "group"));
+            Check("place.set.group", groupRefusal == null, groupRefusal ?? "");
            yield return new WaitForSeconds(4f);

            List<Dictionary<string, object>> each = List("placement:t_each");
            List<Dictionary<string, object>> group = List("placement:t_group");
            Check("place.spawned", each.Count == 3 && group.Count == 3, $"each {each.Count}, group {group.Count}");
+            if (each.Count != 3 || group.Count != 3)
+            {
+                // Everything below needs both sets alive. Take back what was set and end the group, so the run goes on.
+                Api<bool>("RunicNpc_RemovePlacement", "t_each");
+                Api<bool>("RunicNpc_RemovePlacement", "t_group");
+                Note("place: the placements did not spawn, so the rest of the group is skipped");
+                yield break;
+            }

            // each: kill one; the other two stay, and it alone returns after ~20 s.
            var survivors = new HashSet<ulong>(each.Skip(1).Select(x => (ulong)x["netId"]));
--- a/tools/drill/drill.js
+++ b/tools/drill/drill.js
@@ -30,6 +30,20 @@ const BIG = (process.env.DRILL_BIG_RIGS || 'rust-oxide,rust-carbon').split(',')
 const STOPPABLE = process.env.DRILL_STOPPABLE || 'rust-carbon'
 const KITS_URL = 'https://umod.org/plugins/Kits.cs'
 const WAIT_DAYS = 3 // D317: how long a build waits for Oxide to catch up
+const HARNESS_CAP_MS = 45 * 60000 // the whole harness run
+const HARNESS_STALL_MS = 5 * 60000 // no new line in its file for this long: it has stopped (issue #20)
+
+// What a fresh server would not have (issue #20). RunicNPC writes its four example kits once, into
+// Kits' own file, and never again, so a file kept from an older build keeps that build's kits; the drill
+// starts from none of it. Files, never directories: a directory the panel's file API creates is not
+// writable by the game (docs/runicnpc/PLAN.md §1.5), and the game makes these itself on its first boot.
+const FRESH_DATA = [
+  '/oxide/data/Kits/kits_data.json',
+  '/oxide/data/RunicNPC/profiles.json',
+  '/oxide/data/RunicNPC/placements.json',
+  '/oxide/data/RunicNPC/routes.json',
+  '/oxide/data/RunicNPC/state.json',
+]

 const sleep = (ms) => new Promise((r) => setTimeout(r, ms))
 const now = () => new Date().toISOString()
@@ -262,6 +276,7 @@ async function live(a) {
    await p.rm(rig, '/oxide/plugins/RunicNpcTest.cs')
    await p.rm(rig, '/oxide/data/RunicNpcTest.json')
    await p.rm(rig, '/staging-drill.json')
+    for (const f of FRESH_DATA) await p.rm(rig, f) // already gone is fine: rm swallows it

    log(`starting ${RIG} on ${branch}`)
    const started = Date.now()
@@ -310,9 +325,13 @@ async function live(a) {
    result.ran = true
    log('rnt.run all: running')

-    const lines = await waitHarness(p, rig, 45 * 60000)
+    const { lines, ended } = await waitHarness(p, rig, HARNESS_CAP_MS, HARNESS_STALL_MS)
    result.harness = summarise(lines)
-    if (!result.harness.done) finding(`The harness did not finish in 45 minutes (${result.harness.pass} pass, ${result.harness.fail} fail so far).`)
+    if (!result.harness.done) {
+      finding(unfinishedFinding(result.harness, lines, ended))
+      // What the server said while it stalled (an exception in the harness's coroutine lands here, not in its file).
+      result.consoleTail = safeTail(await p.readOr(rig, '/latest.log', ''), 40)
+    }
    for (const f of result.harness.failed) finding(`Harness: ${f}`)
    log(`harness: ${result.harness.pass} pass, ${result.harness.fail} fail`)
    result.oxideErrors = await oxideErrors(p, rig)
@@ -408,15 +427,38 @@ function readJsonText(t) {
  }
 }

-async function waitHarness(p, id, timeoutMs) {
-  const end = Date.now() + timeoutMs
+/**
+ * Where the harness stands, given its lines now and what was last seen of them ({ count, at }): done
+ * (`# done all:`), stalled (no new line for stallMs: it died without saying so, as in issue #20), or running.
+ */
+function harnessProgress(lines, seen, nowMs, stallMs) {
+  if (lines.some((l) => /^# done all:/.test(l))) return { state: 'done', seen }
+  if (lines.length > seen.count) return { state: 'running', seen: { count: lines.length, at: nowMs } }
+  if (nowMs - seen.at >= stallMs) return { state: 'stalled', seen }
+  return { state: 'running', seen }
+}
+
+/** Waits for the harness; `ended` is done, stalled or capped (timeoutMs passed). */
+async function waitHarness(p, id, timeoutMs, stallMs) {
+  const start = Date.now()
  let lines = []
-  while (Date.now() < end) {
+  let seen = { count: 0, at: start }
+  while (Date.now() < start + timeoutMs) {
    await sleep(30000)
    lines = readJsonText(await p.readOr(id, '/oxide/data/RunicNpcTest.json', null)) || lines
-    if (lines.some((l) => /^# done all:/.test(l))) break
+    const v = harnessProgress(lines, seen, Date.now(), stallMs)
+    seen = v.seen
+    if (v.state !== 'running') return { lines, ended: v.state }
  }
-  return lines
+  return { lines, ended: 'capped' }
+}
+
+/** The finding for a harness that never wrote `# done all:`. */
+function unfinishedFinding(h, lines, ended) {
+  const so = `${h.pass} pass, ${h.fail} fail so far`
+  if (ended !== 'stalled') return `The harness did not finish in ${HARNESS_CAP_MS / 60000} minutes (${so}).`
+  const last = (lines[lines.length - 1] || 'no line at all').replace(/`/g, "'").slice(0, 200)
+  return `The harness stopped after \`${last}\` (no output for ${HARNESS_STALL_MS / 60000} minutes; ${so}).`
 }

 function summarise(lines) {
@@ -578,14 +620,19 @@ async function fileIssue(title, body) {

 // ---------------------------------------------------------------- main

-const a = args()
-const commands = { window: window_, gate, live, report }
-const command = commands[a._[0]]
-if (!command) {
-  console.error('usage: node tools/drill/drill.js window|gate|live|report [--state f] [--work dir] [--branch b] [--force]')
-  process.exit(2)
+// The pure parts, for drill.test.js; run as a script, it is the command line.
+module.exports = { harnessProgress, unfinishedFinding, FRESH_DATA, HARNESS_STALL_MS }
+
+if (require.main === module) {
+  const a = args()
+  const commands = { window: window_, gate, live, report }
+  const command = commands[a._[0]]
+  if (!command) {
+    console.error('usage: node tools/drill/drill.js window|gate|live|report [--state f] [--work dir] [--branch b] [--force]')
+    process.exit(2)
+  }
+  command(a).catch((e) => {
+    console.error(e.message || e)
+    process.exit(1)
+  })
 }
-command(a).catch((e) => {
-  console.error(e.message || e)
-  process.exit(1)
-})
--- a/tools/drill/drill.test.js
+++ b/tools/drill/drill.test.js
@@ -0,0 +1,58 @@
+// The drill's pure parts: how it decides the harness has stopped (issue #20), and what it starts clean.
+//   node --test tools/drill/drill.test.js
+
+const test = require('node:test')
+const assert = require('node:assert')
+const { harnessProgress, unfinishedFinding, FRESH_DATA, HARNESS_STALL_MS } = require('./drill.js')
+
+const MIN = 60000
+const T0 = 1000000
+
+test('a harness that keeps writing is running, and its clock restarts on each new line', () => {
+  let v = harnessProgress(['# run all'], { count: 0, at: T0 }, T0 + 30000, HARNESS_STALL_MS)
+  assert.equal(v.state, 'running')
+  assert.deepEqual(v.seen, { count: 1, at: T0 + 30000 })
+  // Four silent minutes, then a line: still running, and the clock restarts.
+  v = harnessProgress(['# run all', 'a: PASS '], v.seen, T0 + 30000 + 4 * MIN, HARNESS_STALL_MS)
+  assert.equal(v.state, 'running')
+  assert.equal(v.seen.at, T0 + 30000 + 4 * MIN)
+})
+
+test('no new line for five minutes is a stall; four minutes and a bit is not', () => {
+  const seen = { count: 2, at: T0 }
+  const lines = ['# run all', 'a: PASS ']
+  assert.equal(harnessProgress(lines, seen, T0 + 5 * MIN - 1, HARNESS_STALL_MS).state, 'running')
+  assert.equal(harnessProgress(lines, seen, T0 + 5 * MIN, HARNESS_STALL_MS).state, 'stalled')
+})
+
+test('a harness that never wrote a line stalls from when the wait began', () => {
+  assert.equal(harnessProgress([], { count: 0, at: T0 }, T0 + 5 * MIN, HARNESS_STALL_MS).state, 'stalled')
+})
+
+test('done wins, even when the file has been still for a long time', () => {
+  const lines = ['# run all', '# done all: 10 pass, 1 fail']
+  assert.equal(harnessProgress(lines, { count: 2, at: T0 }, T0 + 30 * MIN, HARNESS_STALL_MS).state, 'done')
+})
+
+test('the stall finding names the last line and the counts', () => {
+  const lines = ['# run all', 'place.set.each: FAIL position: off the navmesh', 'place.spawned: FAIL each 0, group 3']
+  const f = unfinishedFinding({ pass: 40, fail: 2 }, lines, 'stalled')
+  assert.equal(f, 'The harness stopped after `place.spawned: FAIL each 0, group 3` (no output for 5 minutes; 40 pass, 2 fail so far).')
+})
+
+test('a backtick in the last line cannot break the issue body, and a long line is cut', () => {
+  const f = unfinishedFinding({ pass: 0, fail: 0 }, ['x`y' + 'z'.repeat(500)], 'stalled')
+  assert.equal(f.split('`').length, 3)
+  assert.ok(f.length < 330)
+  assert.match(unfinishedFinding({ pass: 0, fail: 0 }, [], 'stalled'), /stopped after `no line at all`/)
+})
+
+test('a capped wait keeps the 45-minute message', () => {
+  assert.equal(unfinishedFinding({ pass: 3, fail: 1 }, ['# run all'], 'capped'), 'The harness did not finish in 45 minutes (3 pass, 1 fail so far).')
+})
+
+test('the clean start deletes files only: every path ends in .json and none is a directory', () => {
+  assert.ok(FRESH_DATA.includes('/oxide/data/Kits/kits_data.json'))
+  assert.ok(FRESH_DATA.includes('/oxide/data/RunicNPC/state.json'))
+  for (const f of FRESH_DATA) assert.match(f, /^\/oxide\/data\/(Kits|RunicNPC)\/[a-z_]+\.json$/)
+})