From 99a4002ffb7df69ed63599c3dc6b5e7209c8bdad Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 2 Jul 2026 19:05:47 +0000 Subject: [PATCH] oracle: CD-command trace hook + live-diff localizes Kula World bug 3 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds a CD-command trace to psx-beetle (beetle_cdcmd_trace_hook.patch: callback in cdc.cpp's command dispatch, wired through beetle_libretro.cpp into cdrom_cmd_dump / cdrom_cmd_reset on the oracle debug server). This is the two-process oracle-diff the setup is built for, now working on Linux. Live-diff result (docs/kula-world-findings.md, bug 3): the oracle's game reads level data with a clean Setloc->SeekL->Setmode->ReadN->Pause per sector (SeekL x18, ReadN x22, GetlocL x89). Our runtime's game, in the wedge, issues NEITHER SeekL NOR ReadN — only GetStat/Init/Setloc/Pause, an error/retry branch the oracle never enters. Crucial: our runtime DID deliver 307 sectors during early boot (ReadN + data delivery work). Reads only stop at frame ~890 — the BIOS mid-game region revalidation (ReadTOC+GetID). The region fix made that PASS, but the post-ReadTOC CD state still stops the game resuming reads. Prime suspect: our ReadTOC (case 0x1E) is a bare stat+COMPLETE stub that does not model drive repositioning / the track table the game reads to recompute its seek. Documented for the next session. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01BdjxoRB1f9VQsNzZayCgGS --- docs/beetle-linux.md | 5 ++ docs/beetle_cdcmd_trace_hook.patch | 82 ++++++++++++++++++++++++++++++ docs/kula-world-findings.md | 50 ++++++++++++------ runtime/src/beetle_debug_server.c | 43 ++++++++++++++++ runtime/src/beetle_libretro.cpp | 47 ++++++++++++++++- 5 files changed, 210 insertions(+), 17 deletions(-) create mode 100644 docs/beetle_cdcmd_trace_hook.patch diff --git a/docs/beetle-linux.md b/docs/beetle-linux.md index f95dd678..3134315e 100644 --- a/docs/beetle-linux.md +++ b/docs/beetle-linux.md @@ -18,8 +18,13 @@ cd beetle-psx git checkout 5759277b # "audit pass" — last C++-tree base we target patch -p1 < ../docs/beetle_wtrace_hook.patch patch -p1 < ../docs/beetle_sio_trace_hook.patch +patch -p1 < ../docs/beetle_cdcmd_trace_hook.patch ``` +`beetle_cdcmd_trace_hook.patch` adds a CD-command trace callback (fires per +command dispatch in cdc.cpp) exposed as the `cdrom_cmd_dump` / `cdrom_cmd_reset` +debug commands — used to oracle-diff the Kula World CD read sequence. + `beetle_sio_trace_hook.patch` adds `FrontIO::SetSIOTraceCallback` (fires per completed SIO byte exchange) — an integration hook beetle_libretro.cpp needs that predated the committed wtrace patch. diff --git a/docs/beetle_cdcmd_trace_hook.patch b/docs/beetle_cdcmd_trace_hook.patch new file mode 100644 index 00000000..9015cf47 --- /dev/null +++ b/docs/beetle_cdcmd_trace_hook.patch @@ -0,0 +1,82 @@ +diff --git a/libretro.cpp b/libretro.cpp +index d2e82bca..e9c867c8 100644 +--- a/libretro.cpp ++++ b/libretro.cpp +@@ -508,6 +508,11 @@ PS_SPU *PSX_SPU = NULL; + PS_CDC *PSX_CDC = NULL; + FrontIO *PSX_FIO = NULL; + ++/* PSXRecomp oracle hooks: NULL when no listener attached. */ ++psxrecomp_wtrace_cb_t g_psxrecomp_wtrace_cb = NULL; ++psxrecomp_fntrace_cb_t g_psxrecomp_fntrace_cb = NULL; ++psxrecomp_cdcmd_cb_t g_psxrecomp_cdcmd_cb = NULL; ++ + MultiAccessSizeMem<512 * 1024, uint32, false> *BIOSROM = NULL; + MultiAccessSizeMem<65536, uint32, false> *PIOMem = NULL; + MultiAccessSizeMem<2048 * 1024, uint32, false> *MainRAM = NULL; +diff --git a/mednafen/psx/cdc.cpp b/mednafen/psx/cdc.cpp +index 1daaa5b7..d62c7ee9 100644 +--- a/mednafen/psx/cdc.cpp ++++ b/mednafen/psx/cdc.cpp +@@ -1318,6 +1318,12 @@ int32_t PS_CDC::Update(const int32_t timestamp) + else + { + const CDC_CTEntry *command = &Commands[PendingCommand]; ++ /* PSXRecomp oracle hook: CD command about to execute. */ ++ if(MDFN_UNLIKELY(g_psxrecomp_cdcmd_cb)) ++ g_psxrecomp_cdcmd_cb(PendingCommand, ArgsReceiveIn, ++ ArgsReceiveIn > 0 ? ArgsReceiveBuf[0] : 0, ++ ArgsReceiveIn > 1 ? ArgsReceiveBuf[1] : 0, ++ ArgsReceiveIn > 2 ? ArgsReceiveBuf[2] : 0); + next_time = (this->*(command->func))(ArgsReceiveIn, ArgsReceiveBuf); + PendingCommandPhase = 2; + } +diff --git a/mednafen/psx/psx.h b/mednafen/psx/psx.h +index 704c0a19..d9538c13 100644 +--- a/mednafen/psx/psx.h ++++ b/mednafen/psx/psx.h +@@ -137,4 +137,44 @@ extern unsigned psx_gpu_overclock_shift; + extern uint8_t analog_combo[2]; + extern uint8_t analog_combo_hold; + ++/* PSXRecomp oracle: SIO byte trace callback. ++ * Fired by FrontIO when a complete byte exchange finishes. */ ++class FrontIO; ++extern FrontIO *PSX_FIO; ++typedef void (*psxrecomp_sio_trace_cb_t)(uint8_t tx, uint8_t rx, uint16_t ctrl); ++ ++/* PSXRecomp oracle: RAM write trace callback. ++ * Fired by PS_CPU::SB/SH/SW after the write completes. ++ * addr = virtual address (caller masks for physical filter) ++ * value = stored value (sized by `size`) ++ * pc = PC of the executing store instruction ++ * ra = $ra (GPR[31]) at time of store, for one frame of caller context ++ * size = 1, 2, or 4 (byte / halfword / word) */ ++typedef void (*psxrecomp_wtrace_cb_t)(uint32_t addr, uint32_t value, ++ uint32_t pc, uint32_t ra, uint8_t size); ++extern psxrecomp_wtrace_cb_t g_psxrecomp_wtrace_cb; ++ ++/* PSXRecomp oracle: function-call (JAL/JALR/J/JR) trace callback. ++ * Fired by PS_CPU on every J/JAL/JR/JALR retire, BEFORE the link write. ++ * Caller filters by target_pc to keep volume bounded. ++ * caller_pc = PC of the J/JAL/JR/JALR instruction ++ * target_pc = computed branch target ++ * parent_ra = GPR[31] at time of call (parent's return address) ++ * a0, a1 = argument registers at time of call ++ * kind = 1=J, 2=JAL, 3=JR, 4=JALR */ ++typedef void (*psxrecomp_fntrace_cb_t)(uint32_t caller_pc, uint32_t target_pc, ++ uint32_t parent_ra, uint32_t a0, ++ uint32_t a1, uint8_t kind); ++extern psxrecomp_fntrace_cb_t g_psxrecomp_fntrace_cb; ++ ++/* PSXRecomp oracle: CD command trace callback. ++ * Fired by PS_CDC just before a command handler executes. ++ * cmd = command byte (0x01 GetStat, 0x02 Setloc, 0x06 ReadN, 0x09 Pause, ++ * 0x0A Init, 0x0E Setmode, 0x15 SeekL, 0x1A GetID, 0x1B ReadS, ...) ++ * nargs = number of argument bytes ++ * arg0..arg2 = first three argument bytes (0 if absent) */ ++typedef void (*psxrecomp_cdcmd_cb_t)(uint8_t cmd, uint8_t nargs, ++ uint8_t arg0, uint8_t arg1, uint8_t arg2); ++extern psxrecomp_cdcmd_cb_t g_psxrecomp_cdcmd_cb; ++ + #endif diff --git a/docs/kula-world-findings.md b/docs/kula-world-findings.md index 8c94503d..c77e88ba 100644 --- a/docs/kula-world-findings.md +++ b/docs/kula-world-findings.md @@ -69,19 +69,37 @@ The 2.5 s cadence is the tell: that is a retry-with-timeout, i.e. the game issues a command, waits ~2.5 s for a completion signal, times out, retries. The signal it waits for is what our controller/IRQ path delivers wrong. -Next investigation options: - 1. Live oracle-diff: rebuild psx-beetle WITH a CD-command trace hook - (mirror the SIO hook in beetle_sio_trace_hook.patch — add a callback - in cdc.cpp's command dispatch), boot it, and compare the boot->demo - CD command/IRQ sequence. Does the oracle's game issue the same - GetStat/Init loop and then proceed? What completion event breaks it - out that ours doesn't? - 2. Game-side: find the CD-init state machine (caller of the command-issue - func_800639C8) and its "init complete" branch condition — which RAM - flag it polls, and which ISR path (game CD IRQ handler) is supposed to - set it. Then check our INT2-COMPLETE delivery for that command against - it (timing of present_cdrom_irq vs the game reading the response). - Suspicion: the second INT (INT2 COMPLETE) for Init/Pause is delivered but - the game's ISR misses latching its done-flag — a delivery-timing race in - present_cdrom_irq's generation latch, the same machinery bug 2's SeekL - fix (c146b95) touched. +### Oracle-diff result (DONE — divergence localized) + +Built a CD-command trace hook into psx-beetle (beetle_cdcmd_trace_hook.patch: +a callback in cdc.cpp's command dispatch + `cdrom_cmd_dump` / `cdrom_cmd_reset` +debug commands on the oracle) and captured its boot->demo CD command stream. + +The oracle's game reads level data with a clean per-sector pattern: + Setloc(LBA) -> SeekL -> Setmode(0x80) -> ReadN -> Pause (x22 ReadN) +plus GetlocL (0x10) position polling (x89). It issues SeekL 18x and ReadN 22x. + +Our runtime's game, in the wedge window, issues **NEITHER SeekL NOR ReadN** — +only GetStat/Init/Setloc/Pause. So our game took an error/retry branch the +oracle never enters. + +CRUCIAL timeline fact: our runtime DID deliver 307 sectors successfully during +early boot (so ReadN + sector-data delivery WORK). Reading only stops at +frame ~890 — the moment the BIOS does its mid-game region revalidation +(ReadTOC + GetID). After that revalidation the game can never resume reading; +it drops into the GetStat/Init/Setloc/Pause retry loop and stays there. + +So the root cause is narrowed to: the BIOS ReadTOC+GetID revalidation (or the +CD-controller state it leaves behind — drive repositioned to lead-in / TOC, +stat/mode reset) prevents the game's CD driver from resuming reads. The region +fix got the revalidation to PASS, but the post-revalidation CD state still +breaks the resume. The oracle does not perform this mid-game revalidation in +the same way, so it reads continuously. + +Next: diff the CD-controller state (stat, mode, position, motor/seek bits) +immediately AFTER ReadTOC completes, ours vs the oracle. Check whether our +ReadTOC leaves stat/position where the game's resume-read expects it, and +whether the game's post-revalidation Setloc/SeekL is being answered such that +it can re-enter the read state. Prime suspect: our ReadTOC (case 0x1E) is a +bare stat+COMPLETE stub — it does not model the drive repositioning / the +GetTN/GetTD track table the game may read next to recompute where to seek. diff --git a/runtime/src/beetle_debug_server.c b/runtime/src/beetle_debug_server.c index 26659517..15d10480 100644 --- a/runtime/src/beetle_debug_server.c +++ b/runtime/src/beetle_debug_server.c @@ -53,6 +53,14 @@ extern uint32_t beetle_get_sio_trace(uint32_t *out_seq, uint8_t *out_tx, extern uint32_t beetle_get_sio_trace_total(void); extern void beetle_reset_sio_trace(void); +/* CD command trace */ +extern uint32_t beetle_get_cdcmd_trace(uint32_t *out_seq, uint8_t *out_cmd, + uint8_t *out_nargs, uint8_t *out_a0, + uint8_t *out_a1, uint8_t *out_a2, + int max_count); +extern uint32_t beetle_get_cdcmd_trace_total(void); +extern void beetle_reset_cdcmd_trace(void); + /* wtrace */ extern int beetle_wtrace_arm(uint32_t lo, uint32_t hi); extern int beetle_wtrace_disarm(int slot); @@ -379,6 +387,39 @@ static void h_sio_trace(int id, const char *json) { free(seqs); free(txs); free(rxs); free(ctrl); } +static void h_cdrom_cmd_dump(int id, const char *json) { + int count = json_get_int(json, "count", 256); + if (count < 1) count = 1; + if (count > 8192) count = 8192; + + uint32_t *seqs = (uint32_t*)malloc(count * sizeof(uint32_t)); + uint8_t *cmds = (uint8_t*)malloc(count), *nargs = (uint8_t*)malloc(count); + uint8_t *a0 = (uint8_t*)malloc(count), *a1 = (uint8_t*)malloc(count), *a2 = (uint8_t*)malloc(count); + if (!seqs || !cmds || !nargs || !a0 || !a1 || !a2) { + free(seqs); free(cmds); free(nargs); free(a0); free(a1); free(a2); + send_err(id, "alloc"); return; + } + uint32_t got = beetle_get_cdcmd_trace(seqs, cmds, nargs, a0, a1, a2, count); + uint32_t total = beetle_get_cdcmd_trace_total(); + + send_fmt("{\"id\":%d,\"ok\":true,\"total\":%u,\"count\":%u,\"entries\":[", + id, total, got); + for (uint32_t i = 0; i < got; i++) { + if (i > 0) send_fmt(","); + send_fmt("{\"seq\":%u,\"cmd\":\"0x%02X\",\"nargs\":%u," + "\"a0\":\"0x%02X\",\"a1\":\"0x%02X\",\"a2\":\"0x%02X\"}", + seqs[i], cmds[i], nargs[i], a0[i], a1[i], a2[i]); + } + send_fmt("]}\n"); + free(seqs); free(cmds); free(nargs); free(a0); free(a1); free(a2); +} + +static void h_cdrom_cmd_reset(int id, const char *json) { + (void)json; + beetle_reset_cdcmd_trace(); + send_ok(id); +} + static void h_sio_write_window(int id, const char *json) { int which = json_get_int(json, "which", 0); int before = json_get_int(json, "before", 4); @@ -1089,6 +1130,8 @@ static const CmdEntry CMDS[] = { { "screenshot_file", h_screenshot_file }, /* alias */ { "sio_trace_reset", h_sio_trace_reset }, { "sio_trace", h_sio_trace }, + { "cdrom_cmd_dump", h_cdrom_cmd_dump }, + { "cdrom_cmd_reset", h_cdrom_cmd_reset }, { "sio_write_window", h_sio_write_window }, /* wtrace — normalized verb set (parity contract with psx-runtime). */ { "wtrace_arm", h_wtrace_arm }, diff --git a/runtime/src/beetle_libretro.cpp b/runtime/src/beetle_libretro.cpp index ff5e1d41..4c9a828b 100644 --- a/runtime/src/beetle_libretro.cpp +++ b/runtime/src/beetle_libretro.cpp @@ -56,6 +56,22 @@ static void sio_trace_callback(uint8_t tx, uint8_t rx, uint16_t ctrl) { s_sio_trace_idx = (s_sio_trace_idx + 1) % BEETLE_SIO_TRACE_CAP; } +/* ---- CD command trace (oracle-diff for the Kula World CD-init wedge) ---- */ +#define BEETLE_CDCMD_TRACE_CAP 8192 +struct BeetleCdcmdEntry { + uint32_t seq; uint8_t cmd, nargs, a0, a1, a2; +}; +static BeetleCdcmdEntry s_cdcmd_trace[BEETLE_CDCMD_TRACE_CAP]; +static int s_cdcmd_idx = 0; +static uint32_t s_cdcmd_seq = 0; +static void cdcmd_trace_callback(uint8_t cmd, uint8_t nargs, + uint8_t a0, uint8_t a1, uint8_t a2) { + BeetleCdcmdEntry *e = &s_cdcmd_trace[s_cdcmd_idx]; + e->seq = s_cdcmd_seq++; e->cmd = cmd; e->nargs = nargs; + e->a0 = a0; e->a1 = a1; e->a2 = a2; + s_cdcmd_idx = (s_cdcmd_idx + 1) % BEETLE_CDCMD_TRACE_CAP; +} + /* ---- wtrace_all ring (ALWAYS-ON; no filter; captures every write) ---- * Per global rule "ring buffers always-on": every write hits this ring * unconditionally so probes connected late can still query the last ~1s @@ -434,7 +450,8 @@ extern "C" int beetle_init_with_disc(const char *bios_path, const char *disc_pat g_psxrecomp_wtrace_cb = wtrace_callback; g_psxrecomp_fntrace_cb = fntrace_callback; - std::fprintf(stderr, "[psx-beetle] wtrace + fntrace callbacks registered\n"); + g_psxrecomp_cdcmd_cb = cdcmd_trace_callback; + std::fprintf(stderr, "[psx-beetle] wtrace + fntrace + cdcmd callbacks registered\n"); std::fflush(stderr); return 0; @@ -553,6 +570,34 @@ extern "C" void beetle_reset_sio_trace(void) { memset(s_sio_trace, 0, sizeof(s_sio_trace)); } +/* ---- CD command trace accessors ---- */ +extern "C" uint32_t beetle_get_cdcmd_trace(uint32_t *out_seq, uint8_t *out_cmd, + uint8_t *out_nargs, uint8_t *out_a0, + uint8_t *out_a1, uint8_t *out_a2, + int max_count) +{ + int avail = (int)(s_cdcmd_seq < (uint32_t)BEETLE_CDCMD_TRACE_CAP + ? s_cdcmd_seq : BEETLE_CDCMD_TRACE_CAP); + int count = max_count < avail ? max_count : avail; + int start = (s_cdcmd_idx - count + BEETLE_CDCMD_TRACE_CAP) % BEETLE_CDCMD_TRACE_CAP; + for (int i = 0; i < count; i++) { + const BeetleCdcmdEntry *e = &s_cdcmd_trace[(start + i) % BEETLE_CDCMD_TRACE_CAP]; + out_seq[i] = e->seq; + out_cmd[i] = e->cmd; + out_nargs[i] = e->nargs; + out_a0[i] = e->a0; + out_a1[i] = e->a1; + out_a2[i] = e->a2; + } + return (uint32_t)count; +} +extern "C" uint32_t beetle_get_cdcmd_trace_total(void) { return s_cdcmd_seq; } +extern "C" void beetle_reset_cdcmd_trace(void) { + s_cdcmd_idx = 0; + s_cdcmd_seq = 0; + memset(s_cdcmd_trace, 0, sizeof(s_cdcmd_trace)); +} + /* ---- wtrace accessors ---- */ extern "C" int beetle_wtrace_arm(uint32_t lo, uint32_t hi) { if (s_wtrace_range_count >= BEETLE_WTRACE_MAX_RANGES) return -1;