BT410 5.3.57: the crash is deterministic, and the real blocker is the load gate

The previous commit's attribution was wrong and is corrected in the roadmap.

WRONG: 'the crash is the skeleton walk's' rested on 0 crashes in 2 runs with
the walk disabled -- a 25% coin flip presented as evidence.  The oldest
preserved dump has no [skl] line and ends on the old 'couldn't figure out how
to MakeEntityRenderables' fallback, so it predates the walk and faults
identically.

WRONG: 'it lands at different points each time'.  Every dump carries the same
numbers to the byte (cr2 7000FA64, EIP 66D9).  What varies is how far the log
gets, not where the fault is.

Resolving the address through btl4opt.map names it exactly:
EulerAngles::operator=(const LinearMatrix&)+0x19, a read through the matrix
reference.  A binary scan finds all three call sites of that operator pass a
stack local, so the 1.79GB pointer still has no static explanation -- that is
now its own open item rather than a guess.

Two theories killed cleanly by the new BT_STACK_LOG probe and a binary scan:
ESP drift (drift=0 over 2002 frames; exactly one callee-cleans function exists
in the whole binary) and an undersized stack (our PE and the shipped one have
identical 1MB/8K geometry).

What the probe found matters more: the application is parked in state=2, which
is LoadingMission, not WaitingForLaunch.  Priority 0 is where the interest
manager queues renderer events during load, the gate needs that priority empty,
and it never empties -- so the mission never launches and the renderer holds a
blank screen by design.  The fault arrives ~30s into that wait.  Runs that DO
launch never print a single [launch] line.  So 'crashes half the time' and
'hangs during load' are one event seen twice.

A 15x disagreement between two clocks looked like a reconstruction slip --
BTL4.CPP passes GetTicksPerSecond() where ApplicationManager wants a frame
rate.  Checked against the shipped binary before touching it: same instruction
sequence, same kind of static float pushed.  Authentic.  Documented so nobody
'fixes' it.

Also swept every subsystem DefaultData against its real C++ base.  Fifteen
chain past their immediate parent, but fourteen skip only classes that add no
handlers and no attributes, and no class's attribute-ID base disagrees with its
index chain -- so there are no gap slots there.  The one real defect: Generator
is a HeatSink but chained to Subsystem::MessageHandlers, so it ignored every
ToggleCooling message.  Fixed (compiles next build).

Tooling: podrun.sh stages the build over BTL4REC.EXE, exports the host-side VPX
board env -- without which the run dies at the iserver handshake rather than
merely rendering nothing -- and archives every run's log, marking it -CRASH
when it faulted.  Before this the only preserved dump was an accident, on a rig
where each run costs four minutes.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Cyd
2026-07-28 21:41:38 -05:00
co-authored by Claude Fable 5
parent f54e1a3c19
commit 4cf09917ce
9 changed files with 356 additions and 12 deletions
+11 -1
View File
@@ -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
);
+50
View File
@@ -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))
{
+25 -1
View File
@@ -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
@@ -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.