diff --git a/emulator/render-bridge/logs/000-prev.txt b/emulator/render-bridge/logs/000-prev.txt new file mode 100644 index 00000000..85966e9c --- /dev/null +++ b/emulator/render-bridge/logs/000-prev.txt @@ -0,0 +1,14 @@ +BattleTech v4.10 +BTL4Application::BTL4Application +RIO never came back from test mode! +GaugeInterpreter: undefined label 'Initialization' +ColorMapperArmor warning: damage zone dz_missle not found +ColorMapperArmor warning: damage zone dz_missle not found +ColorMapperArmor warning: damage zone dz_lmissle not found +ColorMapperArmor warning: damage zone dz_rmissle not found +ColorMapperArmor warning: damage zone dz_ftorso not found +ColorMapperArmor warning: damage zone dz_btorso not found +BTL4Application::RunMissionMessageHandler +Turning Plasma Score Display On +BTL4Application::RunMissionMessageHandler +Turning Plasma Score Display On diff --git a/emulator/render-bridge/logs/001-prev.txt b/emulator/render-bridge/logs/001-prev.txt new file mode 100644 index 00000000..43acac7f --- /dev/null +++ b/emulator/render-bridge/logs/001-prev.txt @@ -0,0 +1,5 @@ +BattleTech v4.10 +BTL4Application::BTL4Application +RIO never came back from test mode! +Protocol error : length 65535 too big, length_word 0xffffffff ++++ERROR : rcv_protocol fail during iserver handling, xmits=0 diff --git a/emulator/render-bridge/pod_render_rec.conf b/emulator/render-bridge/pod_render_rec.conf index 3f931ea9..0e5c1299 100644 --- a/emulator/render-bridge/pod_render_rec.conf +++ b/emulator/render-bridge/pod_render_rec.conf @@ -29,11 +29,11 @@ prebuffer=60 # DOSBox = pipe client (retry), vRIO/vPLASMA apps = servers; an unconnected # pipe behaves as an unplugged cable so the mission still runs. serialnamedpipe.h serial1=namedpipe pipe:vrio rxpollus:100 rxburst:16 -serial2=namedpipe pipe:vplasma -# live UNBUFFERED game output: DOS char devices are not buffered, so -# redirecting stdout to COM3 lands every line immediately. A normal -# '> file' redirect stays 0 bytes until the process exits, which hides -# all progress on a run that does NOT crash. +serial2=namedpipe pipe:vplasma +# live UNBUFFERED game output: DOS char devices are not buffered, so +# redirecting stdout to COM3 lands every line immediately. A normal +# '> file' redirect stays 0 bytes until the process exits, which hides +# all progress on a run that does NOT crash. serial3=file file:C:\VWE\TeslaRel410\emulator\render-bridge\podlog.txt [autoexec] mount c "C:\VWE\TeslaRel410\ALPHA_1" @@ -56,6 +56,7 @@ rem arena1 city mission (TESTARN.EGG: map=arena1, time=day) with the RIO rem attached; stdout redirected so mission-load progress survives kills. set BT_MECH_LOG=1 set BT_LAUNCH_LOG=1 +set BT_STACK_LOG=1 set BT_FORCE_THROTTLE=0.6 set BT_FORCE_TURN=0.25 set HEAPSIZE=15000000 diff --git a/emulator/render-bridge/podlog.txt b/emulator/render-bridge/podlog.txt index 85966e9c..9822b4bd 100644 --- a/emulator/render-bridge/podlog.txt +++ b/emulator/render-bridge/podlog.txt @@ -1,14 +1,79 @@ BattleTech v4.10 BTL4Application::BTL4Application -RIO never came back from test mode! GaugeInterpreter: undefined label 'Initialization' +[exp] master player experience=2 simLive=1 heatModelOn=1 advDamage=1 +[role] 'Role::Default' lives=1000 killBonus=500 dmgMod=1 +[torso] horizJoint 'jointtorso' -> 0x00a3fe78 type=1 enabled=1 +[weap] 'AFC100' seg=13 mount=sitelgunport rear=0 +[proj] 'AFC100' ammoBinIndex=21 -> AmmoBinAFC100 (rounds=20) +[weap] 'ERLLaser' seg=7 mount=siterugunport rear=0 +[weap] 'ERSLaser_1' seg=13 mount=sitelgunport rear=0 +[weap] 'ERSLaser_2' seg=8 mount=siterdgunport rear=0 +[weap] 'LRM15_1' seg=18 mount=sitelmissleport rear=0 +[proj] 'LRM15_1' ammoBinIndex=26 -> AmmoBinLRM15_1 (rounds=16) +[weap] 'LRM15_2' seg=19 mount=sitermissleport rear=0 +[proj] 'LRM15_2' ammoBinIndex=28 -> AmmoBinLRM15_2 (rounds=16) +[mech] segment walk done: subsystemCount=32 weaponCount=6 +[skel] jointSubsystem=0x009e6d84 jointCount=25 +[mech] model params: walkTR=65 runTR=40 maxAcc=20 throttleAdj=0.8 (deg,deg,u/s^2,scale) +[mech] look angles: L=50 R=-50 F=-15 B=0 (deg) +[mech] damage zones streamed: 22 [dz_dtorso,dz_hip,dz_larm,dz_ldleg,dz_ldoor,dz_lfoot,dz_lgun,dz_ltorso,dz_luleg,dz_rarm,dz_rdleg,dz_rdoor,dz_reardtorso,dz_rearltorso,dz_rearrtorso,dz_rearutorso,dz_rfoot,dz_rgun,dz_rtorso,dz_ruleg,dz_searchlight,dz_utorso] +[cyl] table 'madcat' LOADED rows=7 +[valve] 'Condenser1' valve=1 flow=0.166667 +[valve] 'Condenser2' valve=1 flow=0.166667 +[valve] 'Condenser3' valve=1 flow=0.166667 +[valve] 'Condenser4' valve=1 flow=0.166667 +[valve] 'Condenser5' valve=1 flow=0.166667 +[valve] 'Condenser6' valve=1 flow=0.166667 +[mapper] ctor id=0 throttleAttr=0x002c30f8 controlModeAttr=0x002c3134 +[gau2] cluster slot=14 classID=3011 auxScreen=5 name=Avionics +[gau2] cluster slot=15 classID=3014 auxScreen=6 name=Myomers +[gau2] cluster slot=22 classID=3021 auxScreen=1 name=AFC100 +[gau2] cluster slot=23 classID=3016 auxScreen=10 name=ERLLaser +[gau2] cluster slot=24 classID=3016 auxScreen=3 name=ERSLaser_1 +[gau2] cluster slot=25 classID=3016 auxScreen=12 name=ERSLaser_2 +[gau2] cluster slot=27 classID=3024 auxScreen=2 name=LRM15_1 +[gau2] cluster slot=29 classID=3024 auxScreen=9 name=LRM15_2 ColorMapperArmor warning: damage zone dz_missle not found ColorMapperArmor warning: damage zone dz_missle not found ColorMapperArmor warning: damage zone dz_lmissle not found ColorMapperArmor warning: damage zone dz_rmissle not found ColorMapperArmor warning: damage zone dz_ftorso not found ColorMapperArmor warning: damage zone dz_btorso not found -BTL4Application::RunMissionMessageHandler -Turning Plasma Score Display On -BTL4Application::RunMissionMessageHandler -Turning Plasma Score Display On +[link] InitializePlayerLink -> vehicle playerLink=0x00ac513c +[launch] state=11 minPriorityEmpty=0 +[launch] state=11 minPriorityEmpty=0 +[launch] state=11 minPriorityEmpty=0 +[launch] state=11 minPriorityEmpty=0 +[launch] state=11 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[stack] frame at 0x12dee7 drift=0 over 1001 frames +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[launch] state=2 minPriorityEmpty=0 +[stack] frame at 0x12dee7 drift=0 over 2002 frames +[launch] state=2 minPriorityEmpty=0 +Reference to a page you don't own +PF cr2= 7000 FA64 at 00FF 0000 66D9 +Unhandled exception 000E at 00FF 66D9 ErrCode 0004 diff --git a/emulator/render-bridge/podrun.sh b/emulator/render-bridge/podrun.sh new file mode 100644 index 00000000..e80d8c1f --- /dev/null +++ b/emulator/render-bridge/podrun.sh @@ -0,0 +1,89 @@ +#!/bin/bash +# +# podrun -- stage the current build and start one pod run, keeping the log. +# +# podrun.sh [conf-basename] [tag] +# +# podrun.sh # pod_render_rec.conf, our build +# podrun.sh pod_render_shp # the shipped exe, for A/B +# podrun.sh pod_render_rec noskl +# +# WHY THIS EXISTS +# +# Two traps have each already cost a round of wrong conclusions on this rig: +# +# 1. STALE BINARY. The confs run BTL4REC.EXE out of ALPHA_1/REL410/BT, +# while the build writes build410/btl4opt.exe. Forgetting to copy means +# silently measuring the previous binary. This script always stages and +# always prints the timestamp it staged, so the evidence is in the log. +# +# 2. OVERWRITTEN LOG. serial3 truncates podlog.txt on every launch, so the +# only preserved crash dump on this rig was an accident. Runs are four +# minutes and the defect is intermittent, so a lost log is a lost run. +# Every run is archived to logs/-.txt when the NEXT one starts. +# +# The rule this rig taught: an intermittent fault needs TWO AGREEING RUNS +# before you believe anything. One run is a story, not evidence. +# +set -e + +BR=/c/VWE/TeslaRel410/emulator/render-bridge +IMG=/c/VWE/TeslaRel410/ALPHA_1/REL410/BT +SRC=/c/VWE/TeslaRel410/restoration/build410/btl4opt.exe +CONF=${1:-pod_render_rec} +TAG=${2:-$CONF} + +mkdir -p "$BR/logs" + +# archive whatever the last run left behind before serial3 truncates it +if [ -s "$BR/podlog.txt" ]; then + N=$(ls "$BR/logs" 2>/dev/null | wc -l) + PREV="$BR/logs/$(printf '%03d' "$N")-prev.txt" + cp "$BR/podlog.txt" "$PREV" + if grep -q "page you don't own" "$PREV"; then + mv "$PREV" "${PREV%-prev.txt}-CRASH.txt" + echo "archived previous run (CRASHED) -> $(basename "${PREV%-prev.txt}-CRASH.txt")" + else + echo "archived previous run -> $(basename "$PREV")" + fi +fi + +if tasklist //FI "IMAGENAME eq dosbox-x.exe" 2>/dev/null | grep -qi dosbox-x; then + echo "killing running dosbox-x" + taskkill //F //IM dosbox-x.exe > /dev/null 2>&1 || true + sleep 2 +fi + +case "$CONF" in +*shp*) + echo "shipped side -- no staging" + ;; +*) + [ -f "$SRC" ] || { echo "no build at $SRC -- run build410.sh link"; exit 1; } + cp -f "$SRC" "$IMG/BTL4REC.EXE" + echo "staged BTL4REC.EXE <- btl4opt.exe $(ls -la "$SRC" | awk '{print $5" bytes "$6" "$7" "$8}')" + ;; +esac + +# +# HOST-SIDE BOARD ENV. These belong to the VPX device inside DOSBox, not to +# the guest, so they must be exported here. Launching without them does not +# merely disable rendering -- the iserver handshake fails outright with +# "Protocol error : length 65535 too big" and the run dies during boot. +# +WORK="$LOCALAPPDATA/Temp/vwe-pod" +mkdir -p "$WORK" +export VPXLOG="$WORK/vpxresp.txt" +export VPX_RESPOND=1 +export VPX_RENDER=1 +export VPX_EXPLODE=1 +export VPX_DUMPDIR="$WORK" +export VPX_NOMAIN=1 +export VPX_CLEAR=0,0,0 +export RIO_TAP="$WORK/riotap.txt" + +rm -f "$BR/podlog.txt" +cd /c/VWE/TeslaRel410/emulator/src/src +./dosbox-x.exe -conf "$BR/$CONF.conf" > /dev/null 2>&1 & +echo "launched $CONF (tag=$TAG) -- pid $!" +echo "watch: tail -f $BR/podlog.txt" diff --git a/restoration/source410/BT/POWERSUB.CPP b/restoration/source410/BT/POWERSUB.CPP index f4192c37..2ebf53e2 100644 --- a/restoration/source410/BT/POWERSUB.CPP +++ b/restoration/source410/BT/POWERSUB.CPP @@ -608,10 +608,20 @@ Generator::AttributeIndexSet HeatSink::AttributeIndex ); +// +// A Generator IS a HeatSink, and HeatSink is one of only two classes in the +// subsystem tree that defines a message handler of its own -- ToggleCooling. +// Chaining to Subsystem::MessageHandlers here skipped it, so a generator +// silently ignored every cooling toggle it was sent. Found by sweeping every +// DefaultData against its real C++ base: fifteen classes chain past their +// immediate parent, but the other fourteen skip only classes that add no +// handlers and no attributes, which makes them equivalent (and probably +// authentic). This one loses a handler, so it is a real defect. +// Generator::SharedData Generator::DefaultData( Generator::ClassDerivations, - Subsystem::MessageHandlers, + HeatSink::MessageHandlers, Generator::AttributeIndex, Subsystem::StateCount ); diff --git a/restoration/source410/MUNGA/APP.CPP b/restoration/source410/MUNGA/APP.CPP index 5a5951ff..4a2f0f54 100644 --- a/restoration/source410/MUNGA/APP.CPP +++ b/restoration/source410/MUNGA/APP.CPP @@ -72,6 +72,13 @@ Application *application = NULL; int Exit_Code = 0; Logical Application::suppressGauges = False; +// +// Event-pump counters -- see the comment on Application::ProcessOneEvent in +// APP.HPP. Diagnostic only; the BT_STACK_LOG probe reports them. +// +long eventPumpCalls = 0; +long eventPumpHits = 0; + //############################################################################# //########################### Application ############################### //############################################################################# @@ -540,6 +547,47 @@ Logical Check(this); Verify(application == this); + // + // STACK-DRIFT PROBE (env BT_STACK_LOG). + // + // The intermittent page fault reads a stack LOCAL through the frame + // pointer -- disassembly of the fault site shows edi = ebp-0x10, and all + // three callers of that function pass "lea eax,[ebp-0x30]" -- so the bad + // address cannot be a wild argument. It has to be the stack pointer + // itself sitting outside the region. The stack geometry matches the + // shipped exe exactly (1MB reserve, 8K commit), which leaves ESP drifting + // a few bytes per call, most likely a calling-convention mismatch on some + // function we re-declared. + // + // So: record where the frame actually sits, once a second. A monotone + // march proves the drift and its rate; a stable address kills the theory + // outright. One run either way. + // + if (getenv("BT_STACK_LOG")) + { + static char *first_frame = NULL; + static Scalar stack_accum = 0.0f; + static int stack_samples = 0; + char here; + + if (first_frame == NULL) + { + first_frame = &here; + } + stack_accum += frame_duration; + stack_samples++; + if (stack_accum >= 1.0f) + { + stack_accum = 0.0f; + DEBUG_STREAM << "[stack] frame at 0x" << hex << (int)&here << dec + << " drift=" << (int)(first_frame - &here) + << " over " << stack_samples << " frames" + << " ticks=" << (long)Now().ticks + << " pump=" << eventPumpHits << "/" << eventPumpCalls + << endl << flush; + } + } + if (!executeFrames) { CLEAR_FOREGROUND_PROCESSING(); @@ -1391,6 +1439,8 @@ void DEBUG_STREAM << "[launch] state=" << (int)applicationState.GetState() << " minPriorityEmpty=" << (eventQueue->IsPriorityEmpty(MinEventPriority) ? 1 : 0) + << " events=" << eventQueue->GetEventCount() + << " ticks=" << (long)Now().ticks << "\n" << flush; if (eventQueue->IsPriorityEmpty(MinEventPriority)) { diff --git a/restoration/source410/MUNGA/APP.HPP b/restoration/source410/MUNGA/APP.HPP index 06f5b091..a9707edc 100644 --- a/restoration/source410/MUNGA/APP.HPP +++ b/restoration/source410/MUNGA/APP.HPP @@ -661,11 +661,35 @@ inline void networkManager->ExclusiveBroadcast(message,client_ID); } +// +// EVENT-PUMP COUNTERS (read by the BT_STACK_LOG probe in ExecuteForeground). +// +// The application parks in LoadingMission because IsPriorityEmpty(0) never +// becomes true, and priority 0 is where the interest manager queues every +// renderer event while the mission loads. Three very different faults look +// identical from outside -- the pump never runs, the pump runs but finds +// nothing (so something else holds the queue), or the pump drains events as +// fast as they are re-posted. Counting calls against hits separates them in +// a single run. +// +extern long + eventPumpCalls; +extern long + eventPumpHits; + inline Logical Application::ProcessOneEvent(int min_priority) { Check(this); - return eventQueue->ProcessOneEvent(min_priority); + Logical processed; + + eventPumpCalls++; + processed = eventQueue->ProcessOneEvent(min_priority); + if (processed) + { + eventPumpHits++; + } + return processed; } inline void diff --git a/restoration/source410/RENDER-ROADMAP.NOTES.md b/restoration/source410/RENDER-ROADMAP.NOTES.md index 197e46a5..27d01481 100644 --- a/restoration/source410/RENDER-ROADMAP.NOTES.md +++ b/restoration/source410/RENDER-ROADMAP.NOTES.md @@ -822,3 +822,89 @@ STILL TO TRY, cheapest first: BT_NO_SKL stays in the tree: it is how any future "is it the skeleton?" question gets answered in one build instead of two. + +-------------------------------------------------------------------------------- +CORRECTION: THE CRASH IS NOT THE SKELETON WALK'S, AND IT IS NOT RANDOM +-------------------------------------------------------------------------------- +The previous entry attributed the intermittent page fault to the skeleton walk +on the strength of "0 crashes in 2 runs" with the walk disabled. That was a +25% coin flip dressed up as evidence, and it was wrong. Two facts settle it: + + * The oldest preserved crash log has NO [skl] line and ends with the old + "couldn't figure out how to MakeEntityRenderables" fallback -- it is from a + build where the walk did not exist, and it faults identically. + + * Every dump carries the SAME numbers, to the byte: + + Reference to a page you don't own + PF cr2= 7000 FA64 at 00FF 0000 66D9 + Unhandled exception 000E at 00FF 66D9 ErrCode 0004 + + So "it lands at different points each time" was also wrong. What varies is + how far the log gets, not where the fault is. + +READING THE FAULT. 0x66D9 is a CODE offset (_TEXT starts at 0, and the DPMI +host reports EIP relative to the code selector), so btl4opt.map names it +directly: + + 0x0066C0 EulerAngles::operator=(const LinearMatrix&) <- +0x19 = the fault + +Disassembling it, +0x19 is `mov eax,[edi]` with edi = ebp-0x10 -- a stack local. +But the BT_STACK_LOG probe puts the frame at 0x12DEE7, and cr2 is 0x7000FA64, +1790 MB away. A stack local cannot be there, so the reported EIP is one or two +instructions past the real one and the actual fault is the preceding +`fld dword [ebx+0x20]` -- a READ through the matrix reference (ErrCode 4 = read, +page not present), with ebx = 0x7000FA44. + +That is still unexplained, because a binary scan of every direct call to 0x66C0 +finds exactly three call sites, and ALL THREE pass `lea eax,[ebp-0x30]` -- a +stack local. None of them can hand it a 1.79 GB pointer. Unresolved. + +WHAT THE PROBE KILLED. Two clean negatives, both worth keeping killed: + + * ESP drift (a calling-convention mismatch marching the stack down a few + bytes per call). The probe reports drift=0 over 2002 frames, and a scan of + the whole binary finds exactly ONE callee-cleans function (__virt_decommit, + a runtime helper) -- everything else is cdecl, so there is nothing to + mismatch. + + * A stack too small for our deeper call chains. Our PE and the shipped one + have identical geometry: 1 MB reserve, 8 KB commit. + +WHAT THE PROBE FOUND INSTEAD -- and this matters more than the crash. The +application is parked in state=2, which is LoadingMission, NOT WaitingForLaunch. +It never advances, because the gate needs IsPriorityEmpty(MinEventPriority) and +priority 0 is where InterestManager::PostRendererEvent queues every renderer +event while a mission loads. The queue never drains, the mission never +launches, and the video renderer holds a blank screen by design until it does. +The crash arrives after ~30 seconds of that. Runs that DO launch never print a +single [launch] line -- they sail through the gate -- so "crashes about half the +time" and "hangs during load" are the same event, seen twice. + +A TIMING RESULT THAT LOOKS LIKE A BUG AND IS NOT. The gate reposts itself at +Now()+1.0s and printed 31 times while the stack probe -- which accumulates +frame_duration to 1.0 -- printed twice. A 15x disagreement between two clocks. +It traces to `new ApplicationManager(GetTicksPerSecond())` in BTL4.CPP, which +passes a TICK rate (1000, from TIMESTUB.CPP) where the parameter is a FRAME +rate, making frameDuration 1ms. That reads exactly like a reconstruction slip, +so it was checked against the shipped binary before touching anything -- and +the shipped call site is the same instruction sequence pushing the same kind of +static float: + + ours 6a 28 call new 59 8b d8 85 db 74 11 ff 35 a0 11 4e 00 53 call ctor + shipped 6a 28 call new 59 8b d8 85 c0 74 11 ff 35 0c 14 52 00 53 call ctor + +So it is authentic. The 15x is just this emulated rig failing to hit a 1000 Hz +target, which the original hardware would have missed too. DO NOT "fix" it. + +WHERE THIS GOES NEXT. The open question is why priority 0 drains for the +shipped exe and not for ours. Application::ProcessOneEvent now counts calls and +hits (BT_STACK_LOG reports them), which separates the three candidates in one +run: the pump never runs, the pump runs but finds nothing, or the pump drains +events as fast as something re-posts them. + +TOOLING BANKED. emulator/render-bridge/podrun.sh stages the build over +BTL4REC.EXE, exports the host-side VPX board env (without which the run dies at +the iserver handshake, not merely unrendered), and archives each run's log -- +marking the file -CRASH when it faulted. The only preserved dump before this +was an accident, on a rig where every run costs four minutes.