From a2a3f524187cb0ce39a286da5926d006fed787bf Mon Sep 17 00:00:00 2001 From: siruimei07 Date: Thu, 8 Oct 2026 18:47:53 +0800 Subject: [PATCH] feedback7 G-TOOLS: SP_VERIFY re-runs slice work in the existing 8 ms budget instead of blocking the event loop (PR #352 by @siruimei07) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Applied as-is. All-mode verification runs the existing HeadlessJob in headlessSliceMs slices (8 ms on a real scheduler; synchronous when that value is not finite, including the virtual scheduler). The field still settles with the server digest. Sample mode still accepts the client result immediately and logs afterwards. A comparison error in all mode falls back to the server result. Dispose cancels the pending slice timer. Tests: node --test test/match/verification-slices.test.js — 11 pass, 0 fail; node --test test/match/clientCombat.test.js test/match/clientCombat-review.test.js — 39 pass, 0 fail. --- server/match/Match.js | 4 +- server/match/match/clientCombat.js | 8 +- server/match/match/reports.js | 88 ++++++--- test/match/verification-slices.test.js | 249 +++++++++++++++++++++++++ 4 files changed, 317 insertions(+), 32 deletions(-) create mode 100644 test/match/verification-slices.test.js diff --git a/server/match/Match.js b/server/match/Match.js index b95e5bb4..65f40713 100644 --- a/server/match/Match.js +++ b/server/match/Match.js @@ -106,7 +106,7 @@ // (g.bandFocus → timeoutBand); g.unitStats answers m.unitStats: the stats the board's units start their next battle with. // opts.clientCombat default true (env SP_COMBAT=server → false: the legacy server-run + snapshot streaming mode) // opts.verify 'off' | 'sample' | 'all' (env SP_VERIFY, default 'off'): re-simulate accepted client results -// ('sample': ~1 in 8, in a later callback, mismatches logged; 'all': before accepting — the +// ('sample': ~1 in 8, in later slices, mismatches logged; 'all': before accepting — the // server's result wins on a mismatch) // // Engine-only extra options (tests / tools; the lobby never passes them): @@ -121,7 +121,7 @@ // opts.botSliceMs wall-clock ms of rehearsal per scheduler callback (default 8 with a real scheduler, unbounded // with a virtual one); the rest runs in later callbacks (scheduleBotPrep) // opts.headlessSliceMs wall-clock ms per callback of a server-run normal / 联防 field (client-side combat: bots, -// takeovers; default 8 with a real scheduler, at once with a virtual one) +// takeovers, result verification; default 8 with a real scheduler, at once with a virtual one) // Seats may be all bots (tools/matchrun.mjs); the lobby always has ≥ 1 human. // // Diagnostics: m.errors / m.errorCount (engine), m.dispatcher.errors / .errorsByKey (meta handlers), m.simErrors diff --git a/server/match/match/clientCombat.js b/server/match/match/clientCombat.js index 3b78229d..a62b9004 100644 --- a/server/match/match/clientCombat.js +++ b/server/match/match/clientCombat.js @@ -24,8 +24,9 @@ export class MatchClientCombat { _clearFieldTimers(f) { if (!f || !f.cc) return; - for (const k of ['deadlineTimer', 'doneTimer', 'waitTimer', 'sliceTimer']) if (f[k]) { this.cancel(f[k]); f[k] = null; } + for (const k of ['deadlineTimer', 'doneTimer', 'waitTimer', 'sliceTimer', 'verifyTimer']) if (f[k]) { this.cancel(f[k]); f[k] = null; } f.job = null; + f.verifyJob = null; } /** A client-combat field record: the JSON BattleSpec of its Battle options plus the authority / result state. */ @@ -84,7 +85,7 @@ export class MatchClientCombat { return { t: 'b.start', battleId: f.battleId, fieldId: f.fieldId, kind: f.kind, spec: this.spectators.has(pid) ? this._spectatorSpec(f) : f.spec, - authoritative: !!(!f.done && f.mode === 'client' && f.authority === pid && !watch), + authoritative: !!(!f.done && !f.verifyJob && f.mode === 'client' && f.authority === pid && !watch), startAt: f.startAt, serverNow: this.sched.now(), elapsed: Math.round(this._fieldElapsed(f) * 1000) / 1000, speed: this.gameSpeed, watch: !!watch, done: !!f.done, }; @@ -121,6 +122,7 @@ export class MatchClientCombat { /** A client field's result deadline: its time limit on the field clock + RESULT_GRACE_MS (then the server takes over). */ _armDeadline(f) { if (f.deadlineTimer) { this.cancel(f.deadlineTimer); f.deadlineTimer = null; } + if (f.verifyJob) return; const lim = f.spec.timeLimit > 0 ? f.spec.timeLimit : 60; const at = f.startAt + Math.round((lim / this.gameSpeed) * 1000) + RESULT_GRACE_MS; f.deadlineTimer = this.later(Math.max(0, at - this.sched.now()), () => { @@ -225,7 +227,7 @@ export class MatchClientCombat { /** An authoritative human disconnected / left: normal & 联防 fields → server takeover; boss → the partner or the server. */ _authorityLost(ps, why) { for (const f of this.fields) { - if (!f.cc || f.done || f.mode !== 'client' || f.authority !== ps.playerId) continue; + if (!f.cc || f.done || f.verifyJob || f.mode !== 'client' || f.authority !== ps.playerId) continue; if (f.kind === 'boss' || f.kind === 'hidden') this._bossHandover(f, why); else this._runOnServer(f, why); } diff --git a/server/match/match/reports.js b/server/match/match/reports.js index 1ee18482..065ede77 100644 --- a/server/match/match/reports.js +++ b/server/match/match/reports.js @@ -5,7 +5,7 @@ // Installed on Match.prototype by server/match/Match.js (a method container: never instantiated; `this` is the match). import { ERR } from '../../../shared/constants.js'; -import { runHeadless, syntheticResult, validateClientResult, HARD_CAP_SECONDS } from '../fields.js'; +import { HeadlessJob, syntheticResult, validateClientResult, HARD_CAP_SECONDS } from '../fields.js'; import { resultDigest, compactResult as compactForVerify } from '../../sim/spec.js'; import { OK, fail } from './common.js'; @@ -18,7 +18,7 @@ export class MatchReports { _onProgress(ps, msg) { if (!this.clientCombat) return fail(ERR.WRONG_PHASE, 'server-run combat'); const f = this._fieldByBattle(msg.battleId); - if (!f || f.done || f.mode !== 'client' || f.authority !== ps.playerId) return OK; + if (!f || f.done || f.verifyJob || f.mode !== 'client' || f.authority !== ps.playerId) return OK; const p = f.progress; const maxTotal = Math.max(p.total, (f.spec.spawns.length + 1) * 400); p.gt = Math.max(p.gt, Math.min(Number(msg.gt) || 0, HARD_CAP_SECONDS)); @@ -46,7 +46,7 @@ export class MatchReports { _onResult(ps, msg) { if (!this.clientCombat) return fail(ERR.WRONG_PHASE, 'server-run combat'); const f = this._fieldByBattle(msg.battleId); - if (!f || f.done || f.heldResult || f.mode !== 'client' || f.authority !== ps.playerId) return OK; + if (!f || f.done || f.heldResult || f.verifyJob || f.mode !== 'client' || f.authority !== ps.playerId) return OK; const bossLike = f.kind === 'boss' || f.kind === 'hidden'; const v = validateClientResult(f.spec, msg.result, { gd: this.gd }); if (!v.ok) { @@ -57,7 +57,7 @@ export class MatchReports { else this._runOnServer(f, 'invalid'); return OK; } - let result = v.result; + const result = v.result; if (bossLike) { // the final b.progress normally carried everything; the result's per-player damage is a lower bound const by = {}; @@ -91,13 +91,15 @@ export class MatchReports { return OK; } this._bossResultDamage(f, result); - } else { - result = this._verifyResult(f, result); } - f.result = result; - f.resultSource = 'client'; - this._fieldDone(f); - if (bossLike) { this._checkFinalEnd(); this._broadcastPool(false); } + const accept = (verified) => { + f.result = verified; + f.resultSource = 'client'; + this._fieldDone(f); + if (bossLike) { this._checkFinalEnd(); this._broadcastPool(false); } + }; + if (bossLike) accept(result); + else this._verifyResult(f, result, accept); return OK; } @@ -107,27 +109,59 @@ export class MatchReports { } /** - * SP_VERIFY: re-simulate an accepted client result ('all': now, the server's result wins on a mismatch; 'sample': - * ~1 battle in 8 in a later callback, mismatches are only logged). + * SP_VERIFY: re-simulate in headless slices. 'all' waits before accepting (the server wins on a mismatch); + * 'sample' accepts immediately and only logs differences for ~1 battle in 8, even after the field's phase ends. */ - _verifyResult(f, result) { - if (this.verifyMode === 'off') return result; - const check = () => { - const run = runHeadless(this._specBattle(f.spec), { players: f.players }); - const mine = validateClientResult(f.spec, compactForVerify(run.result), { gd: this.gd }); - const server = mine.ok ? mine.result : run.result; - this.verifyStats.checked++; - if (resultDigest(server).hash !== resultDigest(result).hash) { - this.verifyStats.mismatches++; - this.log.warn?.(`[match ${this.roomCode}] ${f.fieldId}: client result differs from the server's simulation`); - return server; + _verifyResult(f, result, accept) { + if (this.verifyMode === 'off') { accept(result); return; } + const required = this.verifyMode === 'all'; + const start = () => { + const job = new HeadlessJob(this._specBattle(f.spec), { players: f.players, onError: (e) => this.reportError('verify', e) }); + if (required) { + // The result has arrived: duplicate reports, disconnects and the old deadline must not start another run. + f.verifyJob = job; + this.cancel(f.deadlineTimer); + f.deadlineTimer = null; + f.rearmDeadline = false; } - return null; + const schedule = () => { + const timer = this.later(0, slice); + if (required) f.verifyTimer = timer; + }; + const slice = () => { + if (required) f.verifyTimer = null; + if (this.disposed || this.ended) return; + if (required && (f.verifyJob !== job || f.done || f.mode !== 'client' || !this.fields.includes(f))) return; + let verified = result; + try { + if (!job.run(this.headlessSliceMs)) { schedule(); return; } + const run = job.output(); + const mine = validateClientResult(f.spec, compactForVerify(run.result), { gd: this.gd }); + const server = mine.ok ? mine.result : run.result; + this.verifyStats.checked++; + if (resultDigest(server).hash !== resultDigest(result).hash) { + this.verifyStats.mismatches++; + this.log.warn?.(`[match ${this.roomCode}] ${f.fieldId}: client result differs from the server's simulation`); + verified = server; + } + } catch (e) { + this.reportError('verify', e); + if (required) { + this._clearFieldTimers(f); + this._runOnServer(f, 'verify-error'); + } + return; + } + if (required) { f.verifyJob = null; accept(verified); } + }; + if (Number.isFinite(this.headlessSliceMs)) schedule(); + else slice(); // Virtual schedulers retain their synchronous fast path. }; - if (this.verifyMode === 'all') return check() || result; + if (required) { start(); return; } let h = 0; for (let i = 0; i < f.battleId.length; i++) h = (h * 31 + f.battleId.charCodeAt(i)) >>> 0; - if (h % 8 === 0) this.later(0, () => { try { check(); } catch (e) { this.reportError('verify', e); } }); - return result; + // Sample jobs use only match-level timers: field completion must not cancel the diagnostic work. + if (h % 8 === 0) this.later(0, start); + accept(result); } } diff --git a/test/match/verification-slices.test.js b/test/match/verification-slices.test.js new file mode 100644 index 00000000..8939bdf5 --- /dev/null +++ b/test/match/verification-slices.test.js @@ -0,0 +1,249 @@ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { setTimeout as pause } from 'node:timers/promises'; +import { PHASE } from '../../shared/constants.js'; +import { runHeadless, validateClientResult, RESULT_GRACE_MS } from '../../server/match/fields.js'; +import { RealScheduler } from '../../server/match/scheduler.js'; +import { compactResult, createBattleFromSpec, resultDigest } from '../../server/sim/spec.js'; +import { makeMatch } from './harness.js'; + +const SLICE_MS = 0.000001; + +function combat(t, verify = 'all', options = {}) { + const h = makeMatch({ mode: 'coop', humans: 1, bots: 0, seed: 345, clientCombat: true, + clients: false, verify, headlessSliceMs: SLICE_MS, timerScale: 0, ...options }); + t.after(() => h.m.dispose()); + h.start(); + assert.ok(h.drive(() => h.m.phase === PHASE.COMBAT)); + return h; +} + +function results(h, f) { + const run = runHeadless(createBattleFromSpec(f.spec, h.m.ds, { recordEvents: false, quiet: true }), { players: f.players }); + const checked = validateClientResult(f.spec, compactResult(run.result), { gd: h.m.gd }); + assert.ok(checked.ok, checked.reason); + const server = checked.result; + assert.ok(server.perPlayer.p_0.leaked.length > 0, 'the empty board leaks real enemies'); + const forged = structuredClone(server); + forged.killed = forged.total; + Object.assign(forged.perPlayer.p_0, { leaked: [], perfect: true, killed: forged.perPlayer.p_0.total }); + const plausible = validateClientResult(f.spec, forged, { gd: h.m.gd }); + assert.ok(plausible.ok, plausible.reason); + return { server, forged: plausible.result }; +} + +function report(h, f, result) { + assert.deepEqual(h.m.handle('p_0', { t: 'b.result', battleId: f.battleId, result }), { ok: true }); +} + +function observeSimulation(m, onStep = () => {}) { + const seen = { battles: 0, steps: 0 }; + const create = m._specBattle.bind(m); + m._specBattle = (...args) => { + const battle = create(...args); + seen.battles++; + const step = battle.step.bind(battle); + battle.step = (...stepArgs) => { + const result = step(...stepArgs); + seen.steps++; + onStep(battle, seen); + return result; + }; + return battle; + }; + return seen; +} + +test('all verification yields between slices and settles with the synchronous server digest', (t) => { + const h = combat(t); + const m = h.m; + const f = m.fields[0]; + const { server, forged } = results(h, f); + let between = null; + const seen = observeSimulation(m, (battle, state) => { + if (state.steps === 1) h.sched.setTimeout(() => { + between = { steps: state.steps, finished: battle.finished, checked: m.verifyStats.checked, done: f.done }; + }, 0); + }); + report(h, f, forged); + assert.equal(seen.steps, 0, 'report handling schedules simulation without stepping it'); + assert.equal(f.done, false, 'the result awaits verification'); + assert.equal(m.lastResults.has('p_0'), false, 'settlement cannot consume the unverified report'); + assert.ok(h.run(() => m.verifyStats.checked === 1)); + assert.ok(between && between.steps > 0, 'an unrelated timer runs after simulation starts'); + assert.deepEqual([between.finished, between.checked, between.done], [false, 0, false], 'the timer runs between unfinished slices'); + assert.equal(resultDigest(f.result).hash, resultDigest(server).hash, 'sliced verification matches synchronous simulation'); + assert.equal(m.verifyStats.mismatches, 1); + assert.equal(m.verifyStats.rejected, 0, 'the forgery passes plausibility validation'); + h.runToPhase(PHASE.SETTLE); + assert.deepEqual(m.lastResults.get('p_0').leaked, server.perPlayer.p_0.leaked); + assert.equal(m.errorCount, 0); +}); + +for (const verify of ['all', 'sample']) { + test(`${verify} verification lets an unrelated real timer run between battle slices`, async (t) => { + const h = makeMatch({ mode: 'coop', humans: 1, bots: 0, seed: 345, clientCombat: true, + clients: false, verify, headlessSliceMs: SLICE_MS, timerScale: 0 }); + const m = h.m; + // Install the real scheduler before start, while the harness has no queued timers. + const scheduler = new RealScheduler(); + m.sched = scheduler; + t.after(() => { m.dispose(); scheduler.dispose(); }); + const waitFor = async (predicate) => { + const deadline = Date.now() + 10000; + while (!predicate() && Date.now() < deadline) await pause(1); + assert.ok(predicate(), `timed out in phase ${m.phase}`); + }; + h.autoHumans().start(); + await waitFor(() => m.phase === PHASE.COMBAT); + const f = m.fields[0]; + const result = compactResult(runHeadless(createBattleFromSpec(f.spec, m.ds, { recordEvents: false, quiet: true }), { players: f.players }).result); + let between = null; + observeSimulation(m, (battle, seen) => { + if (seen.steps === 1) setTimeout(() => { + between = { steps: seen.steps, finished: battle.finished, checked: m.verifyStats.checked, done: f.done }; + }, 0); + }); + report(h, f, result); + await waitFor(() => between !== null); + assert.ok(between.steps > 0, 'the timer was scheduled by the first actual battle step'); + assert.deepEqual([between.finished, between.checked, between.done], [false, 0, verify === 'sample'], 'Node executes the timer while verification is unfinished'); + await waitFor(() => m.verifyStats.checked === 1); + assert.equal(resultDigest(f.result).hash, resultDigest(result).hash); + assert.equal(m.verifyStats.mismatches, 0); + assert.equal(m.errorCount, 0); + }); +} + +test('duplicate reports during all verification start one simulation and settle once', (t) => { + const h = combat(t); + const m = h.m; + const f = m.fields[0]; + const { forged } = results(h, f); + const seen = observeSimulation(m); + let settlements = 0; + const settle = m.settle.bind(m); + m.settle = (...args) => { settlements++; return settle(...args); }; + report(h, f, forged); + assert.equal(f.done, false, 'the duplicate arrives while verification is pending'); + report(h, f, forged); + assert.ok(h.run(() => seen.steps > 0)); + report(h, f, forged); + h.runToPhase(PHASE.SETTLE); + report(h, f, forged); + assert.equal(seen.battles, 1); + assert.equal(m.verifyStats.checked, 1); + assert.equal(m.verifyStats.mismatches, 1); + assert.equal(settlements, 1); +}); + +test('sample verification keeps the accepted result and finishes after the phase changes', (t) => { + // Seed 345 selects the first field for sampling; zero phase delays let settlement overtake verification. + const h = combat(t, 'sample'); + const m = h.m; + const f = m.fields[0]; + const { forged } = results(h, f); + const seen = observeSimulation(m); + report(h, f, forged); + assert.equal(f.done, true, 'sampling accepts the report immediately'); + assert.equal(seen.steps, 0); + h.runToPhase(PHASE.SETTLE); + assert.equal(m.verifyStats.checked, 0, 'the sampled battle is still running after settlement'); + assert.ok(h.run(() => m.verifyStats.checked === 1)); + assert.equal(m.verifyStats.mismatches, 1); + assert.equal(resultDigest(f.result).hash, resultDigest(forged).hash); + assert.deepEqual(m.lastResults.get('p_0').leaked, [], 'sampling never replaces the accepted result'); + assert.ok(h.logs.warn.some((line) => line.includes('client result differs'))); + assert.equal(m.errorCount, 0); +}); + +for (const event of ['disconnect and reconnect', 'expired deadline']) { + test(`pending all verification does not restart simulation after ${event}`, (t) => { + const h = combat(t); + const m = h.m; + const f = m.fields[0]; + const { forged } = results(h, f); + const seen = observeSimulation(m); + // Leave an already-due deadline callback queued when the result arrives. + if (event === 'expired deadline') h.sched.t += f.spec.timeLimit / m.gameSpeed * 1000 + RESULT_GRACE_MS + 1; + report(h, f, forged); + assert.equal(f.done, false); + if (event === 'disconnect and reconnect') { + m.onDisconnect('p_0'); + m.onReconnect('p_0'); + assert.equal(h.lastTo('p_0', 'b.start').authoritative, false, 'reconnect does not request a second result'); + } + h.runToPhase(PHASE.SETTLE); + assert.equal(seen.battles, 1); + assert.equal(m.verifyStats.takeovers, 0, 'a received result no longer needs a client authority'); + assert.equal(m.verifyStats.checked, 1); + assert.equal(m.verifyStats.mismatches, 1); + }); +} + +test('resuming a solo pause does not rearm a result deadline while verification is pending', (t) => { + const h = combat(t, 'all', { mode: 'solo' }); + const m = h.m; + const f = m.fields[0]; + const { forged } = results(h, f); + const seen = observeSimulation(m); + assert.deepEqual(m.handle('p_0', { t: 'g.pause', on: true }), { ok: true }); + report(h, f, forged); + assert.equal(f.done, false); + assert.deepEqual(m.handle('p_0', { t: 'g.pause', on: false }), { ok: true }); + h.sched.t += f.spec.timeLimit / m.gameSpeed * 1000 + RESULT_GRACE_MS + 1; + h.runToPhase(PHASE.SETTLE); + assert.equal(seen.battles, 1); + assert.equal(m.verifyStats.takeovers, 0); + assert.equal(m.verifyStats.checked, 1); +}); + +test('a verification comparison error falls back to a server result and completes the field', (t) => { + const h = combat(t); + const m = h.m; + const f = m.fields[0]; + const { server, forged } = results(h, f); + const seen = observeSimulation(m); + const create = m._specBattle.bind(m); + m._specBattle = (...args) => { + const battle = create(...args); + if (seen.battles === 1) { + const result = battle.result.bind(battle); + battle.result = () => { + const out = result(); + Object.defineProperty(out.perPlayer.p_0, 'unitStats', { get() { throw new Error('verification result cannot be normalized'); } }); + return out; + }; + } + return battle; + }; + report(h, f, forged); + h.runToPhase(PHASE.SETTLE); + assert.equal(seen.battles, 2, 'the failed comparison is followed by one independent server run'); + assert.equal(f.resultSource, 'server'); + assert.equal(resultDigest(f.result).hash, resultDigest(server).hash, 'fallback never accepts the forged result'); + assert.equal(m.errorCount, 1); + assert.ok(h.logs.error.some((line) => line.includes('verification result cannot be normalized'))); + assert.deepEqual(h.sched.errors, []); +}); + +for (const verify of ['all', 'sample']) { + test(`dispose stops pending ${verify} verification without later completion`, (t) => { + const h = combat(t, verify, { timerScale: 1 }); + const m = h.m; + const f = m.fields[0]; + const { forged } = results(h, f); + const seen = observeSimulation(m); + report(h, f, forged); + assert.ok(h.run(() => seen.steps > 0)); + assert.equal(m.verifyStats.checked, 0, 'dispose interrupts an unfinished verification'); + m.dispose(); + const steps = seen.steps; + h.sched.runAll({ maxSteps: 10000 }); + assert.equal(seen.steps, steps, 'no further battle steps execute'); + assert.equal(m.verifyStats.checked, 0); + assert.equal(m.verifyStats.mismatches, 0); + assert.equal(f.done, verify === 'sample'); + assert.equal(m.errorCount, 0); + }); +}