harness: the stub level-1 run continues past both DUART failures; correct the "fatal/LED loop" claim

The stub run does not park at HOST PORT - 15. Both DUART failures are reported, the board LED blinks once (finite L3F208660), TYPE 'GO' TO CONTINUE is printed (no input is read), and the level-1 runner continues ('CONTINUING THE TESTS'). The runner never returns to 3F204440, so 3F208060/3F208650 are never executed. The run then wedges at frame ~2839 in a DUART1 counter-ready interrupt storm: the ISR polls DUART1 reg 5 (bit 0x06400050) and always reads 0x08; the counter runs in timer mode (ACR=0x60) with CTUR/CTLR never programmed, so MAME re-arms at 1 tick and the interrupt re-asserts every ~229 CPU cycles. Frames at 3500 / 6000 / 12000 are byte-identical; RAM differs by one byte. Corrects README.md and annotates GATE_CLEANUP_REPORT.md, BRINGUP_LOG.md and DUART_REPORT.md. Adds a console+PC/milestone instrument and the finding report.
2026-10-30 12:03:54 +02:00 · 2026-10-16 14:56:47 +03:00
1 parent 7296a86034
commit 41454d5d4c
@@ -613,6 +613,16 @@ Captured:
   `0x0F48`, `0x1008`). So the firmware loops: run a test -> fail -> restart with
   interrupts off -> run again.

+> **CORRECTION (2026-10-16, later).** Point 3 is not where the stub level-1 run
+> ends. Breakpoints on `3F208060`/`3F208650` fire **0** times in 20 000 frames,
+> and the level-1 runner never returns to the boot loop's `3F204440 jane
+> L3F208060`. The DUART failures are reported, the finite `L3F208660` blink runs,
+> `TYPE 'GO' TO CONTINUE` is printed (no input is read), and the runner
+> **continues** (`CONTINUING THE TESTS`), then wedges in a **DUART1 counter-ready
+> interrupt storm** from frame ~2839. See `LEVEL1_CONTINUE_REPORT.md`. The
+> "restart" reading above came from a 3000-frame window that ended during the
+> LED blink.
+
 **The causal chain is now complete and consistent:**

 > video memory not modelled -> the level-1 video RAM test fails -> error 22 is reported ->
@@ -1,5 +1,13 @@
 # DUART — wiring MAME's SCN2681 at the host-port window

+> **CORRECTION (2026-10-16, later).** The line 356 note — "an earlier note in
+> this project records that INTENB never enables, because the level-0 restart
+> enters at `3F208060` with `DINT`" — is wrong on both halves: `3F208060` is
+> never entered on the stub level-1 path (measured), and the run does enable
+> interrupts. The level-1 DUART failures are reported and the runner continues,
+> then dies in a **DUART1 counter-ready interrupt storm** (ISR reg 5 = `0x08`)
+> from frame ~2839; see `harness/mame/LEVEL1_CONTINUE_REPORT.md`.
+
 Bounded task, 2026-10-16. Goal: make the firmware's level-1 **HOST PORT** test pass
 (DUART1 channel A) by modelling the DUART with MAME's `SCN2681`, so that
 `'LEVEL1/2 ERROR -> HOST PORT - 15 '` stops appearing in the console capture.
@@ -1,5 +1,15 @@
 # `VT1200_*` env-gate cleanup — outcome

+> **CORRECTION (2026-10-16, later).** This report's `no-env` section says the run
+> goes "up to the HOST PORT test (then the LED loop)" and calls
+> `3F2088B0/3F208B20/3F208A80/3F208950` "the LED loop". Measured over 20 000
+> frames (`harness/mame/LEVEL1_CONTINUE_REPORT.md`), those PCs are inside the
+> **finite** one-shot blink `L3F208660`; `3F208060`/`3F208650` are never executed
+> and the run does not end there. The DUART failures are followed by
+> `CONTINUING THE TESTS` and then a **DUART1 counter-ready interrupt storm** from
+> frame ~2839. The baseline values below are unchanged; only the "LED loop"
+> reading is corrected.
+
 Executes `docs/superpowers/plans/2026-10-16-env-gate-cleanup.md`. The working
 configuration is now the **default**: a bare `vt1200 vt1200` (no env at all)
 behaves exactly like the old incantation
@@ -0,0 +1,151 @@
+# The stub run does NOT park at HOST PORT — it continues, then dies in a DUART1 counter storm
+
+Date: 2026-10-16. Configuration: `./run.sh stub` (`VT1200_IO_PATH_STUB=1`), no other
+env. ROM `vt1200_v22.bin` md5 `b46a3e442ccb86134d2356bd70d22fd2` (unmodified).
+
+This report corrects a claim that stood as fact in
+`reference/level1-bypass-analysis.md` Q4 and shaped the wording of
+`harness/mame/README.md`: **"a level-1 failure is fatal: the runner returns
+nonzero → `3F204440 jane L3F208060` → an infinite board-LED loop at
+`3F208650 jruc L3F208060`."** Measured, that is wrong for the DUART failures. (The file
+`reference/level1-bypass-analysis.md` is outside this task's owned paths, so its
+Q4 text is **not** edited here; this report is the correction of record and the
+owner should annotate it in place.)
+
+All timings are **screen frames** (the firmware's own refresh), sampled once per
+emulated frame. Instrumentation: `harness/mame/console_frames.lua`,
+`harness/mame/wall_hist.lua`, and breakpoints on the sites named below; frames
+and VRAM/RAM dumped via the driver's `VT1200_DUMP_*` knobs. Console output is the
+firmware's own printer (`0x3FDE00C0`), captured to MAME `debug.log` with
+`-debuglog`; the on-screen text is from the frame dumps.
+
+## Timeline (across time, not one snapshot)
+
+| frame | what happens |
+|---|---|
+| 0–1 | level 0 passes (stub); level-1 runner entered (`3FDF72D0`, called from `3F204400`); `LEVEL1/2 TESTING **` printed |
+| 470–481 | HOST PORT test runs; it enables DUART1 interrupts (IMR = `0x07`→`0x01`→`0x07`, channel A) |
+| 484 | HOST PORT fails: dispatcher `3FDF0630` code `0x400` → handler `3FDE9D70` prints `LEVEL1/2 ERROR -> HOST PORT - 15`, dumps `BAUD ERROR 00900040` / `FRAME & OVERRUN ERROR 00030000` / `INTERRUPT REG BIT 00000002`, prints `BLINKING SYSTEM BOARD LED`, calls `L3F208660` (one **finite** two-digit blink, error code `0x15`) |
+| 484–1534 | the blink's `dsjs` delay loops dominate the CPU (hottest PC `3F2088B0`, etc.) |
+| 1534 | handler prints `TYPE 'GO' TO CONTINUE`, then `jauc L3FDF1010` |
+| 1534→1627 | `L3FDF1010` takes the **return** branch (status word `*A13(0xFFA0)` is zero) → the runner continues to the next test |
+| 1613–1624 | PRINTER PORT test runs; enables DUART1 channel-B interrupts (IMR = `0x70`→`0x10`→`0x70`) |
+| 1627 | PRINTER PORT fails: code `0x800` → `LEVEL1/2 ERROR -> PRINTER PORT - 16`, same three diagnostics, `BLINKING SYSTEM BOARD LED`, `L3F208660` blink (code `0x16`); **on-screen text reads `CONTINUING THE TESTS`** |
+| 2759 | `TYPE 'GO' TO CONTINUE` again; returns via `L3FDF1010`; runner continues and draws the weave |
+| **2839** | the next level-1 test enables **only** the DUART1 counter-ready interrupt: `L3FA78A10` writes IMR = `0x08` (last IMR write of the run) |
+| 2839→end | **DUART1 counter-ready interrupt storm.** Frame samples are 100 % inside the DUART1 interrupt path (`00000F60` INT1 trampoline → `3FA92F40` → dispatcher `L3FA78D90`); the DUART1 IRQ re-asserts every ~229 CPU cycles |
+| 3500, 6000, 12000 | frame dumps are **byte-identical**; RAM at 3500 vs 12000 differs in **one byte** (offset `0x4E105`). Still storming at frame 20000 |
+
+So the owner's two observations are exact: (1) after each DUART failure, after a
+finite delay (~1050 frames ≈ 15 s of the blink), it **continues**; (2) then it
+gets **stuck** — at frame 2839.
+
+## The "continues" is not a timeout and not the prompt
+
+The error handler `L3FDE9D70` ends
+
+```
+3fdea470: move a11, *a14+, 1
+3fdea490: calla L3F208660          ; ONE finite blink of the LED error code
+3fdea4e0: movi 0x3fdcd2a8, a9      ; "TYPE 'GO' TO CONTINUE"
+3fdea520: calla L3FDE00C0          ; print it
+3fdea550: jauc  L3FDF1010
+```
+
+and the shared exit is
+
+```
+L3FDF1010:
+3fdf1010: move *a13(0xffa0), a11, 1
+3fdf1030: jreq L3FDF10A0           ; status == 0  -> skip the blink, return
+3fdf1040: move a14, -*sp, 1
+3fdf1070: calla L3FDF1270          ; status != 0  -> the INFINITE LED blink
+L3FDF10A0:
+3fdf10a0: ... rets 2
+```
+
+Facts:
+
+* `3F208060` / `3F208650` are **never executed** in this run. Breakpoints on
+  both fired **0** times over 20 000 frames; so did `3F204440` (the boot loop's
+  `jane L3F208060`) and `3FDF1070` (the call into the truly infinite blink
+  `L3FDF1270`).
+* The blink that *is* seen (`3F2088B0/3F208950/3F208A80/3F208B20`) is inside
+  **`L3F208660`**, a *finite* one-shot blink. The earlier "LED loop" conclusion
+  came from sampling a 900–3000 frame window that ended during the second blink
+  and reading its dominant PC as a wedge.
+* `L3FDF1270` **is** an infinite loop (`3fdf1a80: jruc L3FDF13B0`), but it is
+  only entered when the status word is nonzero. In the observed DUART path the
+  status word is zero, so `L3FDF1010` returns and the runner proceeds.
+* `TYPE 'GO' TO CONTINUE` is **printed, not waited on**: nothing reads DUART2,
+  the keyboard, or any input after it, and no input is faked. The runner
+  continues on its own. There is no keypress and no timeout.
+
+**What is actually true:** a level-1 failure is **reported and the runner
+continues**; it is not by itself fatal. A level-1 failure becomes an infinite
+blink only via `L3FDF1010 → L3FDF1270`, i.e. when the status word
+`*A13(0xFFA0)` is nonzero, which did not happen for these two DUART failures.
+The runner also **never returns** to the boot loop (`3F204440` never fires), so
+`3F208060` plays no part in this path at all.
+
+## The wall, named
+
+In the steady state (frames 2839 → 20 000) the only DUART accesses are a
+repeating pair, ~229 CPU cycles apart:
+
+| logged PC | instruction | access | value |
+|---|---|---|---|
+| `3FA78E30` | `3FA78E10  move *a11(0x50), a7, 0` | DUART1 **ISR**, reg 5, firmware bit address **`0x06400050`** | **`0x0008`** (bit 3 = counter/timer ready) |
+| `3FA7B5E0` | `3FA7B5C0  move *a7(0xf0), a7, 0` | DUART1 reg **0xF**, firmware bit address **`0x064000F0`** (write-only; reads `0xFF`) | `0x00FF` |
+
+(The logged PC trails the memory instruction by one word — TMS34010 prefetch —
+so the reading instruction is the one quoted.)
+
+* `L3FA78D90` (the DUART1 ISR dispatcher) computes `pending = ISR & IMR` into RAM
+  `0x270820`, tests bit 2, then 6, then 1, later **bit 3** at `3FA7B4D0`, clears
+  the software bit, and reads reg `0xF`. But the hardware ISR bit 3 is set again
+  before the read even retires, and `reti` re-enters immediately.
+* Cause: the counter is in **timer mode** — `L3FA71CB0` writes `ACR = 0x60`
+  (reg 4) once — and **CTUR/CTLR (regs 6/7) are never written**, so the reload
+  value is `0`. MAME's `mc68681` re-arms with `std::max(CTR, 1)` = **1 tick** at
+  the 3.6864 MHz DUART clock (271 ns), so the counter-ready interrupt is
+  re-asserted far faster than the ~229-cycle ISR can clear it. The interrupt is
+  therefore permanently pending and the CPU never runs mainline code again.
+* **What it waits for:** ISR bit 3 (`0x08`) to be clear, i.e. `ISR & IMR == 0`.
+  It never is.
+* **What is missing:** a sane counter/timer period. With the reload left at `0`,
+  the model produces the fastest possible tick rather than a long one; the
+  firmware's counter interrupt becomes a storm. This lives in the MAME
+  `mc68681` model (`devices/machine/mc68681.cpp`), which is out of scope here
+  (MAME tree is not owned by this task) — reported, not changed. The local MAME
+  edits (`harness/mame/mame_edits/`) are unrelated (Rx overrun latch, TxRDY
+  timing); this is upstream `max(CTR,1)` behaviour.
+
+## Next wall
+
+**DUART1 counter-ready interrupt storm.** CPU is 100 % inside the DUART1 INT1
+ISR; it polls DUART1 ISR (reg 5, bit `0x06400050`) and always reads `0x08`
+(counter ready); the counter runs in timer mode (`ACR = 0x60`) with an
+unprogrammed reload (`CTUR/CTLR = 0`), so the interrupt re-arms every ~229 CPU
+cycles and can never be cleared. Nothing else executes; the screen has been
+frozen since frame 2839.
+
+Reproduce:
+
+```sh
+M=/home/arti/code/k-space/mame0289/vt1200
+# transcript + milestones (writes debug.log)
+VT1200_IO_PATH_STUB=1 CF_FRAMES=20000 $M vt1200 -rompath harness/mame/roms \
+  -video none -sound none -nothrottle -debug -debugger none -debuglog \
+  -autoboot_script harness/mame/console_frames.lua -autoboot_delay 0
+# final-state histogram, plus DUART access log
+VT1200_IO_PATH_STUB=1 W_START=5000 W_END=12000 \
+  VT1200_DUARTLOG=/tmp/duart.log $M vt1200 -rompath harness/mame/roms \
+  -video none -sound none -nothrottle -debug -debugger none \
+  -autoboot_script harness/mame/wall_hist.lua -autoboot_delay 0
+# frames at increasing times
+VT1200_IO_PATH_STUB=1 VT1200_DUMP_FRAMES=500,1627,2800,3500,12000 \
+  VT1200_DUMP_DIR=/tmp VT1200_DUMP_VRAM_FRAMES=500,2800,12000 \
+  $M vt1200 -rompath harness/mame/roms -video none -sound none -nothrottle \
+  -seconds_to_run 200
+```
@@ -111,10 +111,21 @@ is carefully, because it is easy to misread:
 * It is **off by default**. A bare run still fails level 0 exactly as before and
  says so. This is deliberate: the faithful configuration stays the default.

-With the stub on the boot clears level 0 and reaches **level 1's `HOST PORT - 15`**
-(and `PRINTER PORT - 16`), which is the faithful ceiling. It does **not** produce a
-booted OS: level 1 still fails on the DUART fidelity ceiling, so
-`VT1200_SKIP_LEVEL1=1` remains the only route to X11.
+With the stub on the boot clears level 0 and reaches level 1, where the DUART
+tests fail: `HOST PORT - 15`, then `PRINTER PORT - 16`. **It does not park at
+`HOST PORT - 15`.** Each failure is reported, the board LED blinks once (finite),
+the firmware prints `TYPE 'GO' TO CONTINUE` (which nothing answers and which does
+not wait), and the runner **continues**. It then enables DUART1's counter-ready
+interrupt and **wedges in a DUART1 interrupt storm** — that is the faithful
+ceiling, not `HOST PORT - 15`. It does **not** produce a booted OS. See
+`LEVEL1_CONTINUE_REPORT.md`.
+
+There is **no infinite board-LED loop** on this path. `3F208060`/`3F208650` are
+never executed here, and the boot loop's `3F204440 jane L3F208060` is never
+reached (the level-1 runner never returns). The blink that is seen is the finite
+`L3F208660` called by the error handler. A level-1 failure is fatal only through
+`L3FDF1010 → L3FDF1270`, the genuinely infinite blink, which is entered when the
+status word `*A13(0xFFA0)` is nonzero; the DUART failures leave it zero.

 ### How far the OS gets

@@ -187,10 +198,14 @@ PC=3FDCE400 samples=53 (75 distinct PCs)
 ```

 That is a genuine move, not a false pass: with the count-only level-0 test
-satisfied, the run leaves the level-0 wait and executes level-0/level-1 work, then
-parks at **level 1's `HOST PORT - 15`** (verified from the console transcript:
-`LEVEL1/2 TESTING **`, then `LEVEL1/2 ERROR -> HOST PORT - 15`). It is recorded as a
-*different* baseline because it is opt-in; the default must stay `samples=198`.
+satisfied, the run leaves the level-0 wait and executes level-0/level-1 work. It
+is **not** parked at `HOST PORT - 15`: the console transcript continues
+(`LEVEL1/2 TESTING **`, `LEVEL1/2 ERROR -> HOST PORT - 15`,
+`LEVEL1/2 ERROR -> PRINTER PORT - 16`, `TYPE 'GO' TO CONTINUE`), and the run ends
+in a DUART1 counter-ready **interrupt storm** (from frame ~2839; PC in the DUART1
+INT1 ISR, polling ISR reg 5 = `0x08`). See `LEVEL1_CONTINUE_REPORT.md`. It is
+recorded as a *different* baseline because it is opt-in; the default must stay
+`samples=198`.

 It is a change detector, not a specification. If it moves without you meaning it
 to, find out why.
@@ -0,0 +1,48 @@
+-- console_frames.lua -- the firmware console transcript WITH frame numbers.
+--
+-- Break on the printer entry 0x3FDE00C0 (a9 = message bit pointer) and on the
+-- error-report dispatcher and the level-1 runner, so the transcript is
+-- interleaved with the control-flow milestones.  Output goes to MAME's
+-- debug.log (run with -debuglog); stdout only carries frame summaries.
+--
+--   CF_FRAMES=<n>  budget (default 20000)
+--
+--   <mame> vt1200 ... -debug -debugger none -debuglog \
+--       -autoboot_script harness/mame/console_frames.lua -autoboot_delay 0
+
+local machine = manager.machine
+local dbg = machine.debugger
+local cpu = machine.devices[':maincpu']
+
+if not dbg then
+	print("ERROR: debugger not enabled; pass -debug")
+	machine:exit()
+	return
+end
+
+FRAME = 0
+
+dbg:command('bpset 3fde00c0,,{ printf "P fr=%d a9=%08X\\n", FRAME, a9 ; g }')
+dbg:command('bpset 3fdf72d0,,{ printf "RUNNER-ENTRY fr=%d a3=%08X\\n", FRAME, a3 ; g }')
+dbg:command('bpset 3f204400,,{ printf "L1-CALL fr=%d\\n", FRAME ; g }')
+dbg:command('bpset 3f204440,,{ printf "L1-GATE fr=%d a8=%08X\\n", FRAME, a8 ; g }')
+dbg:command('bpset 3f204460,,{ printf "L1-ZERO-LOOPBACK fr=%d\\n", FRAME ; g }')
+dbg:command('bpset 3f208060,,{ printf "LED-RESTART fr=%d a10=%08X\\n", FRAME, a10 ; g }')
+dbg:command('bpset 3f208660,,{ printf "LED-BLINK fr=%d a10=%08X\\n", FRAME, a10 ; g }')
+dbg:command('bpset 3fde9d70,,{ printf "ERR-HOSTPORT fr=%d\\n", FRAME ; g }')
+dbg:command('bpset 3fdf0630,,{ printf "ERR-DISPATCH fr=%d a8=%08X a10=%08X\\n", FRAME, a8, a10 ; g }')
+
+local maxframes = tonumber(os.getenv("CF_FRAMES") or "20000")
+emu.register_frame_done(function()
+	FRAME = FRAME + 1
+	if FRAME % 2000 == 0 then
+		print(string.format("frame %d PC=%08X", FRAME, cpu.state['PC'].value))
+	end
+	if FRAME >= maxframes then
+		print("done (" .. FRAME .. " frames)")
+		machine:exit()
+	end
+end, "vt1200-cf")
+
+dbg.visible_cpu = cpu
+dbg.execution_state = 'run'
@@ -0,0 +1,57 @@
+MAME debugger version 0.289 (mame0289-dirty)
+Currently targeting vt1200 (VT1200 X terminal (v2.2 firmware))
+Breakpoint 1 set
+Breakpoint 2 set
+Breakpoint 3 set
+Breakpoint 4 set
+Breakpoint 5 set
+Breakpoint 6 set
+Breakpoint 7 set
+Breakpoint 8 set
+Breakpoint 9 set
+L1-CALL fr=0
+
+RUNNER-ENTRY fr=0 a3=00000000
+
+ERR-DISPATCH fr=1 a8=00000001 a10=00000000
+
+P fr=1 a9=3FDCA8E8
+
+ERR-DISPATCH fr=484 a8=00000400 a10=00000000
+
+ERR-HOSTPORT fr=484
+
+P fr=484 a9=3FDC9C68
+
+P fr=484 a9=0080000C
+
+P fr=484 a9=00C0000C
+
+P fr=484 a9=0100000C
+
+P fr=484 a9=0200000C
+
+LED-BLINK fr=484 a10=00000000
+
+P fr=1534 a9=3FDCD2A8
+
+P fr=1538 a9=0200000C
+
+ERR-DISPATCH fr=1627 a8=00000800 a10=00000000
+
+P fr=1627 a9=3FDC9D78
+
+P fr=1627 a9=0080000C
+
+P fr=1627 a9=00C0000C
+
+P fr=1627 a9=0100000C
+
+P fr=1627 a9=0200000C
+
+LED-BLINK fr=1627 a10=00000000
+
+P fr=2759 a9=3FDCD2A8
+
+P fr=2764 a9=0200000C
+
@@ -0,0 +1,62 @@
+-- wall_hist.lua -- where does the run END UP, and does it keep changing?
+--
+-- Samples the PC once per emulated frame but only counts the window
+-- [W_START, W_END], so the early boot/test phases do not pollute the histogram
+-- of the final state.  Prints a few timestamped PC snapshots so "stuck" is
+-- supported by an across-time comparison, not one sample.
+--
+--   W_START=<frame>   default 5000
+--   W_END=<frame>     default 20000
+--   W_SNAP=<n>        snapshot stride (default 2000)
+--   W_OUT=<file>      printable summary copy
+--
+--   <mame> vt1200 ... -debug -debugger none -debuglog \
+--       VT1200_LOG_UNMAPPED=... VT1200_BOARD_LOG=... VT1200_DUARTLOG=... \
+--       -autoboot_script harness/mame/wall_hist.lua -autoboot_delay 0
+
+local machine = manager.machine
+local dbg = machine.debugger
+local cpu = machine.devices[':maincpu']
+
+if not dbg then
+	print("ERROR: debugger not enabled; pass -debug")
+	machine:exit()
+	return
+end
+
+local wstart = tonumber(os.getenv("W_START") or "5000")
+local wend   = tonumber(os.getenv("W_END") or "20000")
+local snap   = tonumber(os.getenv("W_SNAP") or "2000")
+
+local frames = 0
+local hist, first, last = {}, {}, {}
+
+emu.register_frame_done(function()
+	frames = frames + 1
+	local v = cpu.state['PC'].value
+	if frames >= wstart then
+		hist[v] = (hist[v] or 0) + 1
+		if not first[v] then first[v] = frames end
+		last[v] = frames
+	end
+	if frames % snap == 0 then
+		print(string.format("frame %6d  PC=%08X", frames, v))
+	end
+	if frames >= wend then
+		local n = 0
+		for _ in pairs(hist) do n = n + 1 end
+		print(string.format("--- window [%d,%d]: distinct PCs=%d", wstart, wend, n))
+		print("--- hottest PCs ---")
+		local list = {}
+		for k, c in pairs(hist) do list[#list + 1] = {k, c} end
+		table.sort(list, function(a, b) return a[2] > b[2] end)
+		for i = 1, math.min(25, #list) do
+			print(string.format("  PC=%08X  samples=%d  first=%d  last=%d",
+				list[i][1], list[i][2], first[list[i][1]], last[list[i][1]]))
+		end
+		machine:exit()
+	end
+end, "vt1200-wall")
+
+dbg.visible_cpu = cpu
+dbg.execution_state = 'run'