diff --git a/context/reconstruction-gotchas.md b/context/reconstruction-gotchas.md index ce1237e..bc74979 100644 --- a/context/reconstruction-gotchas.md +++ b/context/reconstruction-gotchas.md @@ -916,3 +916,53 @@ Rules: and hid the copy's writes entirely. Sample **per instance-kind** whenever master and replicant objects share a diagnostic. (See also §gotcha on process-wide statics serving the player's data as the replicant's.) + +## 29. A peer mech does NOT tick before RunningMission — bench-only, and it fakes a replication bug (#148, 2026-08-08) + +`Entity::Execute` (`ENTITY.cpp:556`, real engine source [T0]) calls +`PerformAndWatch` **only** when + +```cpp +application->GetApplicationState() == Application::RunningMission + || application->GetApplicationState() == Application::EndingMission + || IsPreRunnable() +``` + +otherwise it just does `WriteSimulationUpdate`. `Entity::DefaultFlags` is +`DynamicFlag|MasterInstance` — **no `PreRunFlag`**; only `Player` and `Director` +add it in their DefaultFlags, and `Mech::Reset` sets it for a reset MASTER +("a reset master must tick"). A **replicant mech never gets it.** + +So during `LoadingMission` / `WaitingForLaunch` / `LaunchingMission` a peer mech +performs **zero** subsystem ticks, no matter how much correctly-replicated data +is arriving for it. Measured on the observer node: + +``` + 235 [perf-first] mech 3:161 master <- own mech, immediately + 402 [torso-rec-rx] <- peer's torso records start arriving +2754 [perf-first] mech 2:55 REPLICANT <- peer's FIRST performance +2758 [torso] PushTwist COPY <- its torso ticks 4 lines later +2761 [ent-exec] state=5 <- RunningMission +``` + +This is correct engine behaviour, **but it silently corrupts any bench that acts +before the round starts.** `BT_AUTOFIRE`/`BT_GOTO` begin immediately, so early +salvos measure a peer whose torso, gait and subsystems have never run — and the +result reads exactly like a replication failure. It cost a full investigation +(filed as #148) before the app-state trace showed the peer was simply not +executing yet. + +Rules: +(a) **Judge a 2-node bench by PREFIX vs INTERLEAVED, never by raw percentage.** + A clean leading run of failures that stops for good is almost always the + pre-`RunningMission` window; interleaved failures are the real thing. +(b) When a peer looks inert, check `[ent-exec] state=` before suspecting + replication. States: `2` LoadingMission, `3` WaitingForLaunch, + `4` LaunchingMission, `5` RunningMission. +(c) Prefer benches that wait for `RunningMission` before acting — or slice the + log at the transition — otherwise every peer-side metric carries this bias. +(d) The receipts that make this legible: `BT_NET_TRACE` gives `[upd-repl]` + (offered to the performer), `[ent-exec]` (state / preRun / instance) and + `[perf-first]` (one-shot per mech: entity ID + instance at its FIRST + performance). Anonymous per-frame receipts are useless in a 2-node log — + **name the mech.** diff --git a/game/reconstructed/mech4.cpp b/game/reconstructed/mech4.cpp index e01a0b8..34976ba 100644 --- a/game/reconstructed/mech4.cpp +++ b/game/reconstructed/mech4.cpp @@ -2704,6 +2704,27 @@ volatile float gBTReplRenderYaw = -999.0f; void Mech::PerformAndWatch(const Time& till, MemoryStream *update_stream) { + // #148 probe: one-shot per mech, the FIRST time this mech's per-frame + // performance runs. Every other receipt in this file is anonymous, so + // master and replicant lines are indistinguishable in a 2-node log -- which + // is exactly what made the "when does the peer torso start ticking?" search + // go in circles. Name the mech. + if (getenv("BT_NET_TRACE")) + { + static const Mech *s_seen[16]; static int s_seenN = 0; + int known = 0; + for (int si = 0; si < s_seenN; ++si) if (s_seen[si] == this) { known = 1; break; } + if (!known && s_seenN < 16) + { + s_seen[s_seenN++] = this; + DEBUG_STREAM << "[perf-first] mech " << GetEntityID() + << " instance=" << (GetInstance() == Entity::ReplicantInstance + ? "REPLICANT" : "master") + << " this=" << (const void *)this + << " subsysCount=" << subsystemCount << "\n" << std::flush; + } + } + // Frame time slice from the simulation clock (same idiom as Mover::Perform). Scalar dt = till - lastPerformance; lastPerformance = till; diff --git a/scratchpad/night13/missileframe.sh b/scratchpad/night13/missileframe.sh index 151fa2e..95607d2 100644 --- a/scratchpad/night13/missileframe.sh +++ b/scratchpad/night13/missileframe.sh @@ -30,6 +30,22 @@ # -- or B shows segResolved=0 (fell back to the body basis). # NOT REPRODUCED: both sides show the same twistDelta spread. # +# ⚠ READ THE PREFIX, NOT THE PERCENTAGE (learned the hard way, 2026-08-08). +# BT_AUTOFIRE starts shooting IMMEDIATELY, while the app is still in +# WaitingForLaunch/LaunchingMission -- and Entity::Execute (ENTITY.cpp:556, +# real engine source) only calls PerformAndWatch when the state is +# RunningMission/EndingMission or the entity IsPreRunnable(). A REPLICANT mech +# is not pre-runnable (Entity::DefaultFlags has no PreRunFlag; only Player / +# Director add it, and Mech::Reset sets it for a reset MASTER), so a peer mech +# does not tick at all until the round actually starts. Every salvo fired +# before that reads twistDelta=0 legitimately -- the peer has no twist yet. +# That is a BENCH artifact (nobody can fire pre-round in a real match), not a +# defect: it showed up as a clean leading run of zeros, e.g. +# ZZZZ...(60)...ZZZZXXXX...(105)...XXXX +# and the first X lands within a few lines of the RunningMission transition. +# So: judge this bench by whether the failures are a PREFIX (fine) or +# INTERLEAVED (real), never by the raw percentage. +# # Only A fires and only A sweeps its torso, so every REPLICANT line in B's # log is a mirror of an A salvo and the comparison is unambiguous. # ========================================================================= diff --git a/scratchpad/night13/missileframe3.sh b/scratchpad/night13/missileframe3.sh new file mode 100644 index 0000000..d747886 --- /dev/null +++ b/scratchpad/night13/missileframe3.sh @@ -0,0 +1,105 @@ +#!/usr/bin/env bash +# ========================================================================= +# #141 -- "missiles launch along the LEG/FOOT facing, then curve to the +# target -- PEER POV ONLY" (Oracle, night 13: "the emitter is following the +# foot facing"; shooter's own view correct). +# +# WHAT THE CODE SAYS SO FAR. Both sides already pass the mount segment: +# MissileLauncher::FireWeapon (mislanch.cpp:363) and the REPLICANT salvo +# mirror (mislanch.cpp:478) each hand BTPushProjectile +# `GetSegmentIndex() /*task #67 mount frame*/`. BTPushProjectile then +# rotates the authored MuzzleVelocity through +# `seg->GetSegmentToEntity() * localToWorld` -- so the launch direction IS +# the segment's world frame on BOTH nodes. Task #67 fixed exactly this +# symptom once already, master-side ("missiles fire out of his back"). +# +# So if the peer report is real, the difference is NOT which frame is asked +# for -- it is whether the replicant's SEGMENT actually carries the torso +# twist. Torso pushes currentTwist into the skeleton on both paths +# (TorsoSimulation and TorsoCopySimulation both call UpdateJoints), so this +# has to be measured, not reasoned about. +# +# THE MEASUREMENT. New [launchframe] receipt (BT_PROJ_LOG) prints, on both +# nodes, the yaw of the launch forward vs the BODY forward: +# [launchframe] master seg=N segResolved=1 segYaw=.. bodyYaw=.. twistDelta=.. +# [launchframe] REPLICANT seg=N segResolved=1 segYaw=.. bodyYaw=.. twistDelta=.. +# twistDelta is the torso twist expressed in the launch direction. +# +# BUG CONFIRMED: A (master) shows |twistDelta| sweeping well away from 0 +# while B (replicant mirror) stays pinned near 0 +# -- or B shows segResolved=0 (fell back to the body basis). +# NOT REPRODUCED: both sides show the same twistDelta spread. +# +# Only A fires and only A sweeps its torso, so every REPLICANT line in B's +# log is a mirror of an A salvo and the comparison is unambiguous. +# ========================================================================= +set -x +. /c/git/bt411/scratchpad/night6/bench_common.sh +cd /c/git/bt411/content || exit 1 +taskkill //F //IM btl4.exe > /dev/null 2>&1 +sleep 2 +rm -f mf_a.log mf_b.log mf_relay.log +bt_expert_egg MP.EGG MF.EGG +sed -i "s/^map=.*/map=grass/; s/^time=.*/time=day/; s/^vehicle=.*/vehicle=madcat/" MF.EGG + +# B: the OBSERVER. Drives at A so it stays in range, but does NOT fire and +# does NOT sweep -- so every [launchframe] REPLICANT line in mf_b.log is a +# mirror of one of A's salvos. +( export BT_GOTO=enemy BT_GOTO_STOP=150 + export BT_PROJ_LOG=1 BT_MP_LOG=1 BT_TORSO_LOG=1 BT_NET_TRACE=1 + bt_launch mf_b.log MF.EGG 0x0C -net 1601 ) +sleep 2 +# A: the SHOOTER. Sweeps the torso hard so twistDelta is unmistakably +# non-zero at fire time, and autofires missiles at the designated enemy. +( export BT_GOTO=enemy BT_GOTO_STOP=150 + export BT_AUTOFIRE=1 BT_AF_MISSILE=1 BT_AF_PERIOD=7 + export BT_LOCK_SWEEP=0.35 + export BT_PROJ_LOG=1 BT_TORSO_LOG=1 BT_MP_LOG=1 + bt_launch mf_a.log MF.EGG 0x03 -net 1501 ) +sleep 5 +python ../tools/btconsole.py MF.EGG 127.0.0.1:1501 127.0.0.1:1601 > mf_relay.log 2>&1 & +RELAY=$! +sleep 170 +kill $RELAY 2>/dev/null +sleep 3 +bt_kill_ours; sleep 2; taskkill //F //IM btl4.exe > /dev/null 2>&1; sleep 3 + +echo "=================== #141 MISSILE LAUNCH FRAME ===================" +echo "--- did A fire, and did B mirror? ---" +echo -n " A [launchframe] master lines ....... "; grep -ac "launchframe\] master" mf_a.log +echo -n " B [launchframe] REPLICANT lines .... "; grep -ac "launchframe\] REPLICANT" mf_b.log +echo +echo "--- did the segment RESOLVE on each side? (segResolved=0 would be the bug) ---" +echo -n " A segResolved=0 ... "; grep -a "launchframe\] master" mf_a.log | grep -ac "segResolved=0" +echo -n " B segResolved=0 ... "; grep -a "launchframe\] REPLICANT" mf_b.log | grep -ac "segResolved=0" +echo +echo "--- THE COMPARISON: twistDelta spread on each side ---" +python - <<'PY' +import re, io +def stats(path, tag): + v = [] + try: + for ln in io.open(path, encoding="latin-1", errors="replace"): + if "[launchframe] " + tag in ln: + m = re.search(r"twistDelta=([-\d.e+]+)", ln) + if m: + try: v.append(float(m.group(1))) + except ValueError: pass + except IOError: + print(" %s: no log" % tag); return + if not v: + print(" %-9s no samples" % tag); return + a = [abs(x) for x in v] + big = sum(1 for x in a if x > 0.10) # ~5.7 deg -- clearly twisted + print(" %-9s n=%-4d |twistDelta| max=%.4f mean=%.4f >0.10rad: %d (%.0f%%)" + % (tag, len(v), max(a), sum(a)/len(a), big, 100.0*big/len(a))) +stats(r"C:\git\bt411\content\mf_a.log", "master") +stats(r"C:\git\bt411\content\mf_b.log", "REPLICANT") +print() +print(" VERDICT: master twisted + REPLICANT pinned near 0 => #141 CONFIRMED.") +print(" both twisted alike => NOT reproduced.") +PY +echo +echo "--- sample lines, both sides ---" +grep -a "launchframe\] master" mf_a.log | head -4 +grep -a "launchframe\] REPLICANT" mf_b.log | head -4