From a1543090229469455c1006588b7632f4f8b36352 Mon Sep 17 00:00:00 2001 From: MechaCat02 Date: Thu, 9 Jul 2026 21:11:58 +0200 Subject: [PATCH] [Phase A] Expansive extraction tracing: call args, file.read, name-hash probe MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Extend the cvar-gated JSONL event_log tracer to extract Project Sylpheed data/behaviour (reimplementation pivot). All additive, default-off, no behaviour change (golden rule): - Tier 1 (--phase_a_trace_args): fill the previously-empty kernel.call args (raw r3..r10 from PPCContext) + args_resolved.path, routed through the existing export bridge (shim trampoline body-only). - Tier 2 (file.read): resolve NtReadFile handle->path via the object table (LookupObject), emit {handle,path,offset,length,buffer_va} so runtime reads correlate to IPFB TOC entries. - Tier 3 (--phase_a_hash_probe=): mirror audit_61 — a hashprobe HIR trap band (base 300, max 32 PCs) in ppc_hir_builder.cc + native handler TrapPhaseAHashProbe in x64_emitter.cc that derefs r3 as a bounded guest C-string and XELOGIs PHASE-A-HASHPROBE (log-only; cpu backend must not reach kernel event_log). Recovers the custom IPFB name-hash from observed (string -> hash) pairs. New files event_log.{cc,h}; cpu_flags + ppc_hir_builder + x64_emitter are whole-file snapshots (also carry the earlier uncommitted audit_* probe plumbing they share). Cross-build and other instrumentation remain uncommitted. Co-Authored-By: Claude Opus 4.8 --- src/xenia/cpu/backend/x64/x64_emitter.cc | 128 ++++ src/xenia/cpu/cpu_flags.cc | 121 ++++ src/xenia/cpu/cpu_flags.h | 74 +++ src/xenia/cpu/ppc/ppc_hir_builder.cc | 161 +++++ src/xenia/kernel/event_log.cc | 709 +++++++++++++++++++++++ src/xenia/kernel/event_log.h | 191 ++++++ 6 files changed, 1384 insertions(+) create mode 100644 src/xenia/kernel/event_log.cc create mode 100644 src/xenia/kernel/event_log.h diff --git a/src/xenia/cpu/backend/x64/x64_emitter.cc b/src/xenia/cpu/backend/x64/x64_emitter.cc index 5da8f6adc..7fe6247c5 100644 --- a/src/xenia/cpu/backend/x64/x64_emitter.cc +++ b/src/xenia/cpu/backend/x64/x64_emitter.cc @@ -13,6 +13,8 @@ #include #include +#include +#include #include "third_party/fmt/include/fmt/format.h" #include "xenia/base/assert.h" @@ -63,6 +65,111 @@ DEFINE_bool(instrument_call_times, false, "Compute time taken for functions, for profiling guest code", "x64"); #endif + +// AUDIT-061/067: forward decls of probe/watch tables (defined in +// ppc_hir_builder.cc). +namespace xe { +namespace cpu { +namespace audit61 { +const std::vector& pcs(); +} // namespace audit61 +namespace audit67 { +const std::vector& vals(); +} // namespace audit67 +namespace hashprobe { +const std::vector& pcs(); +} // namespace hashprobe +} // namespace cpu +} // namespace xe + +// AUDIT-061: handler for trap codes [200, 232). arg0 carries trap idx +// (trap_code - 200), mapping to ::xe::cpu::audit61::pcs()[idx]. Emits one +// log line per fire with cr0/cr6 LGE flags + key GPRs + LR + tid. +static uint64_t TrapAudit61Branch(void* raw_context, uint64_t idx) { + auto* ctx = reinterpret_cast(raw_context); + const auto& pcs = ::xe::cpu::audit61::pcs(); + uint32_t pc = (idx < pcs.size()) ? pcs[static_cast(idx)] : 0u; + uint32_t tid = 0; + if (ctx->thread_state) { + tid = ctx->thread_state->thread_id(); + } + auto enc = [](uint8_t lt, uint8_t gt, uint8_t eq) { + char buf[4]; + buf[0] = lt ? 'L' : '.'; + buf[1] = gt ? 'G' : '.'; + buf[2] = eq ? 'E' : '.'; + buf[3] = '\0'; + return std::string(buf); + }; + XELOGI( + "AUDIT-061-BR pc={:08X} lr={:08X} cr0={} cr6={} r3={:08X} r4={:08X} " + "r5={:08X} r6={:08X} r31={:08X} tid={}", + pc, static_cast(ctx->lr), + enc(ctx->cr0.cr0_lt, ctx->cr0.cr0_gt, ctx->cr0.cr0_eq), + enc(ctx->cr6.cr6_all_equal, ctx->cr6.cr6_1, ctx->cr6.cr6_none_equal), + static_cast(ctx->r[3]), static_cast(ctx->r[4]), + static_cast(ctx->r[5]), static_cast(ctx->r[6]), + static_cast(ctx->r[31]), tid); + return 0; +} + +// AUDIT-067: handler for trap codes [250, 254). arg0 carries trap idx +// (trap_code - 250), mapping to ::xe::cpu::audit67::vals()[idx]. Fired when +// a 4-byte guest store sees the configured value. The store-emit site stashed +// (pc << 32) | (ea & 0xFFFFFFFF) into ctx->scratch right before the trap. +static uint64_t TrapAudit67ValueWatch(void* raw_context, uint64_t idx) { + auto* ctx = reinterpret_cast(raw_context); + const auto& vals = ::xe::cpu::audit67::vals(); + uint32_t val = + (idx < vals.size()) ? vals[static_cast(idx)] : 0u; + uint32_t pc = static_cast(ctx->scratch >> 32); + uint32_t dst = static_cast(ctx->scratch & 0xFFFFFFFFu); + uint32_t tid = 0; + if (ctx->thread_state) { + tid = ctx->thread_state->thread_id(); + } + XELOGI( + "AUDIT-067-VAL pc={:08X} lr={:08X} val={:08X} dst={:08X} " + "r3={:08X} r4={:08X} r5={:08X} r6={:08X} r31={:08X} tid={}", + pc, static_cast(ctx->lr), val, dst, + static_cast(ctx->r[3]), static_cast(ctx->r[4]), + static_cast(ctx->r[5]), static_cast(ctx->r[6]), + static_cast(ctx->r[31]), tid); + return 0; +} + +// PHASE-A hash probe: trap codes [300, 332). arg0 carries trap idx +// (trap_code - 300) -> ::xe::cpu::hashprobe::pcs()[idx]. Derefs r3 as a guest +// C-string (the archive path being hashed) and logs it with r3..r6 + LR + tid. +// Log-only; observes the same code path the retail binary runs. +static uint64_t TrapPhaseAHashProbe(void* raw_context, uint64_t idx) { + auto* ctx = reinterpret_cast(raw_context); + const auto& pcs = ::xe::cpu::hashprobe::pcs(); + uint32_t pc = (idx < pcs.size()) ? pcs[static_cast(idx)] : 0u; + uint32_t r3 = static_cast(ctx->r[3]); + // Deref r3 as a guest C-string via the flat virtual mapping (bounded). + std::string arg; + if (r3 && ctx->virtual_membase) { + const char* p = + reinterpret_cast(ctx->virtual_membase) + r3; + for (size_t i = 0; i < 128 && p[i]; ++i) { + char c = p[i]; + arg.push_back((c >= 0x20 && c < 0x7f) ? c : '.'); + } + } + uint32_t tid = 0; + if (ctx->thread_state) { + tid = ctx->thread_state->thread_id(); + } + XELOGI( + "PHASE-A-HASHPROBE pc={:08X} lr={:08X} arg=\"{}\" r3={:08X} r4={:08X} " + "r5={:08X} r6={:08X} tid={}", + pc, static_cast(ctx->lr), arg, r3, + static_cast(ctx->r[4]), static_cast(ctx->r[5]), + static_cast(ctx->r[6]), tid); + return 0; +} + namespace xe { namespace cpu { namespace backend { @@ -455,6 +562,27 @@ void X64Emitter::Trap(uint16_t trap_type) { // ? break; default: + // AUDIT-067: trap codes [250, 254) dispatch the value-watch handler. + // arg0 = idx into ::xe::cpu::audit67::vals(). + if (trap_type >= 250 && trap_type < 254) { + CallNative(::TrapAudit67ValueWatch, + static_cast(trap_type - 250)); + break; + } + // AUDIT-061: trap codes [200, 232) dispatch the branch-probe handler. + // arg0 = idx into ::xe::cpu::audit61::pcs(). + if (trap_type >= 200 && trap_type < 232) { + CallNative(::TrapAudit61Branch, + static_cast(trap_type - 200)); + break; + } + // PHASE-A hash probe: trap codes [300, 332). + // arg0 = idx into ::xe::cpu::hashprobe::pcs(). + if (trap_type >= 300 && trap_type < 332) { + CallNative(::TrapPhaseAHashProbe, + static_cast(trap_type - 300)); + break; + } XELOGW("Unknown trap type {}", trap_type); db(0xCC); break; diff --git a/src/xenia/cpu/cpu_flags.cc b/src/xenia/cpu/cpu_flags.cc index 3ff067e15..3065a7363 100644 --- a/src/xenia/cpu/cpu_flags.cc +++ b/src/xenia/cpu/cpu_flags.cc @@ -57,3 +57,124 @@ DEFINE_bool(break_condition_truncate, true, "truncate value to 32-bits", "CPU"); DEFINE_bool(break_on_debugbreak, true, "int3 on JITed __debugbreak requests.", "CPU"); + +// AUDIT-DEMO: smoke marker (memory entry: emulator.cc:225,283). Always-on bool. +DEFINE_bool(audit_demo_setup_trace, true, + "Audit smoke marker: log AUDIT-DEMO-SETUP-BEGIN at emulator setup.", + "Audit"); + +// AUDIT-061: comma-separated list of guest PCs to log on each fire. +// Format: "0xPC1,0xPC2,..." (max 32 PCs). Each fire emits +// AUDIT-061-BR pc=X lr=X cr0=LGE cr6=LGE r3=X r4=X r5=X r6=X r31=X tid=N. +// Default empty (off); no perf cost when empty. +DEFINE_string(audit_61_branch_probe_pcs, "", + "AUDIT-061: CSV of guest PCs to trace (cr0/cr6 + regs/tid).", + "Audit"); + +// AUDIT-067: comma-separated list of u32 values to watch. When non-empty, +// every 4-byte guest store (stw/stwu/stwx/stwux/stmw) emits a runtime +// equality check; matches log AUDIT-067-VAL pc=X lr=X val=X dst=X r3..r6 r31 tid=N. +// Max 4 values. Default empty (off); zero overhead when empty. +DEFINE_string(audit_67_value_watch, "", + "AUDIT-067: CSV of u32 values (max 4) — log every guest " + "store whose value matches.", + "Audit"); + +// AUDIT-068: host-side memory-write watch. See cpu_flags.h header for format. +// Mirrors AUDIT-067 but covers host-side writes (xe::store_and_swap, +// Memory::Zero/Fill/Copy). Empty default = zero cost. +DEFINE_string(audit_68_host_mem_watch_values, "", + "AUDIT-068: CSV of u32 values (max 8) — log every host-side " + "guest-memory write whose value matches.", + "Audit"); +DEFINE_string(audit_68_host_mem_watch_addrs, "", + "AUDIT-068: CSV of guest VAs or VA ranges 'START-END' (max 8) " + "— log every host-side guest-memory write whose guest VA falls " + "within the configured set.", + "Audit"); + +// AUDIT-068 Session 3: read-mode probe. See cpu_flags.h for format. +DEFINE_string(audit_68_host_mem_read_probe, "", + "AUDIT-068 Session 3: CSV of 'VA:SIZE:PERIOD_NS' tuples (max 8) " + "— a dedicated poll thread reads the value at each VA every " + "PERIOD_NS and emits AUDIT-068-READ-CHANGE on transition.", + "Audit"); + +// AUDIT-069: see cpu_flags.h header. Empty default = zero cost. +DEFINE_string(audit_69_event_signal_watch, "", + "AUDIT-069: CSV of guest event-handle IDs (max 4) — log each " + "XEvent::Set / Ke*Event / Nt*Event fire whose target matches.", + "Audit"); +DEFINE_string(audit_69_event_signal_native_ptr, "", + "AUDIT-069: CSV of guest event native VAs (X_KEVENT*) (max 4) " + "— log each set fire whose native pointer matches.", + "Audit"); +DEFINE_bool(audit_69_log_all_sets, false, + "AUDIT-069: when true, log EVERY XEvent::Set/Pulse fire (used " + "for one-run wait→signal correlation across handle drift). " + "Default false; use only with --mute=true.", + "Audit"); + +// AUDIT-070 (S5 of AUDIT-069 family): semaphore-release watch. See header. +DEFINE_string(audit_70_semaphore_release_watch, "", + "AUDIT-070: CSV of guest semaphore handle IDs (max 4) — log " + "each NtReleaseSemaphore / xeKeReleaseSemaphore fire whose " + "target matches.", + "Audit"); +DEFINE_bool(audit_70_log_all_releases, false, + "AUDIT-070: when true, log EVERY NtReleaseSemaphore / " + "xeKeReleaseSemaphore fire (used to identify the work-semaphore " + "handle on first run). Default false; use only with --mute=true.", + "Audit"); + +// Phase A — see kernel/event_log.h. +DEFINE_string(phase_a_event_log_path, "", + "Phase A: write schema-v1 JSONL event log to this path. " + "Empty (default) = disabled.", + "Audit"); +DEFINE_bool(phase_a_event_log_mem_writes, false, + "Phase A: include mem.write events in the JSONL log. RESERVED — " + "not wired in this phase. Default false.", + "Audit"); + +// Phase A — expansive extraction tracing (game-data RE). All default-off so the +// diff-oriented schema-v1 output stays byte-identical when unused. +DEFINE_bool(phase_a_trace_args, false, + "Phase A extraction: populate the kernel.call args (raw r3..r10) and " + "args_resolved (file I/O path/offset/length/buffer, alloc size, " + "handle names) fields, and emit file.read events. Default false.", + "Audit"); +DEFINE_string(phase_a_hash_probe, "", + "Phase A extraction: CSV of guest PCs (max 32). At each, deref r3 " + "as a guest C-string and emit a guest.call event {pc,arg_str," + "r3..r6,tid} — used to recover the IPFB/IDXD name-hash. Default " + "empty (off).", + "Audit"); + +// Phase D Stage 1 — see kernel/event_log.h `EmitContentionObserved`. +DEFINE_bool(kernel_emit_contention, false, + "Phase D Stage 1: emit `contention.observed` events when " + "RtlEnterCriticalSection's spin loop is exhausted and the call " + "falls through to xeKeWaitForSingleObject. Default false (zero " + "cost when disabled). Requires --phase_a_event_log_path to be " + "set as well.", + "Audit"); + +// Phase B — see kernel/phase_b_snapshot.h. +DEFINE_string(phase_b_snapshot_dir, "", + "Phase B: write 5-file structured state snapshot to " + "/canary/ at the moment immediately before the first " + "guest PPC instruction of entry_point. Empty (default) = " + "disabled, zero overhead.", + "Audit"); +DEFINE_bool(phase_b_snapshot_and_exit, false, + "Phase B: after writing the snapshot, exit the process " + "immediately (std::_Exit(0)) so re-runs are byte-deterministic.", + "Audit"); +DEFINE_bool(phase_b_dump_section_content, false, + "Phase B: in memory.json, populate section_contents[].content_b64 " + "with raw bytes of every committed XEX-image region. Default " + "false — per-region SHA-256 is enough for the routine diff; " + "this is the escape hatch for the STOP-and-report condition " + "(image_loaded_sha256 mismatch).", + "Audit"); diff --git a/src/xenia/cpu/cpu_flags.h b/src/xenia/cpu/cpu_flags.h index 38c4f98ba..b23bd8b03 100644 --- a/src/xenia/cpu/cpu_flags.h +++ b/src/xenia/cpu/cpu_flags.h @@ -35,4 +35,78 @@ DECLARE_bool(break_condition_truncate); DECLARE_bool(break_on_debugbreak); +// AUDIT-DEMO smoke marker. +DECLARE_bool(audit_demo_setup_trace); + +// AUDIT-061: multi-PC branch probe — emits one log line per fire with +// (pc, lr, cr0 LGE, cr6 LGE, r3, r4, r5, r6, r31, tid). CSV of guest PCs. +DECLARE_string(audit_61_branch_probe_pcs); + +// AUDIT-067: value-watch — emit a log line for each 32-bit guest store whose +// value-to-be-stored matches any configured value. CSV of u32 values +// ("0xDEADBEEF,..."), max 4 entries. Default empty (off); zero cost when empty. +DECLARE_string(audit_67_value_watch); + +// AUDIT-068: host-side memory-write watch — emit a log line for each host-side +// write to guest memory whose VALUE matches any configured u32 value, or whose +// guest VA falls within any configured ADDR or ADDR-range. Mirrors AUDIT-067 +// but covers the host-side write paths (xe::store_and_swap, Memory::Zero/ +// Fill/Copy) that AUDIT-067's JIT store-opcode hooks cannot see. +// +// VALUES: CSV of u32 values, max 8 entries; e.g. "0x8200A208,0x8200A928". +// ADDRS: CSV of guest VAs or VA ranges, max 8 entries; range form is +// "0xSTART-0xEND" (inclusive). e.g. "0x42500000-0x42600000,0xBCE25340". +// Default empty (off); zero cost on the hot path when both are empty. +DECLARE_string(audit_68_host_mem_watch_values); +DECLARE_string(audit_68_host_mem_watch_addrs); + +// AUDIT-068 Session 3: read-mode probe. CSV of "VA:SIZE:PERIOD_NS" tuples +// (max 8). A dedicated low-priority thread polls each VA every PERIOD_NS and +// emits AUDIT-068-READ-CHANGE when the value transitions. SIZE in {1,2,4,8}. +// Example: "0xBCE25340:4:1000000" = poll u32 at 0xBCE25340 every 1 ms. +// Default empty (off); the poll thread is not spawned when empty. +DECLARE_string(audit_68_host_mem_read_probe); + +// AUDIT-069: event-signal watch. CSV of guest handle IDs (e.g. "0xF8000098") +// to log on every XEvent::Set / KeSetEvent / NtSetEvent / KePulseEvent / +// NtPulseEvent fire whose target matches. Max 4 entries. Default empty (off); +// zero cost on the hot path when empty. +DECLARE_string(audit_69_event_signal_watch); +// AUDIT-069: event-signal watch by native guest VA (X_KEVENT*). CSV of guest +// VAs (max 4). Default empty (off). Use when the handle id varies across +// boots but the native dispatcher pointer is stable. +DECLARE_string(audit_69_event_signal_native_ptr); +// AUDIT-069: when true, log EVERY XEvent::Set / XEvent::Pulse fire (subject +// to the slowpath gate). Use only with --mute=true and short windows — high +// volume. Default false (off). +DECLARE_bool(audit_69_log_all_sets); + +// AUDIT-070 (S5 of AUDIT-069 family): semaphore-release watch. CSV of guest +// handle IDs (e.g. "0xF8000098") to log on every NtReleaseSemaphore / +// xeKeReleaseSemaphore fire whose target matches. Max 4 entries. Default +// empty (off); zero cost on the hot path when empty. +DECLARE_string(audit_70_semaphore_release_watch); +// AUDIT-070: when true, log EVERY NtReleaseSemaphore / xeKeReleaseSemaphore +// fire. Use only with --mute=true and short windows — used to identify the +// canary work-semaphore handle on first run. Default false (off). +DECLARE_bool(audit_70_log_all_releases); + +// Phase A: JSONL event-log emitter path. When non-empty, the engine writes +// schema-v1 JSONL events to this file. Empty (default) = no overhead, no +// behavior change. Schema: xenia-rs/audit-runs/phase-a-diff-harness/schema-v1.md +DECLARE_string(phase_a_event_log_path); +DECLARE_bool(phase_a_event_log_mem_writes); +DECLARE_bool(phase_a_trace_args); +DECLARE_string(phase_a_hash_probe); + +// Phase B: initial-state snapshot. When the dir cvar is non-empty, the +// engine writes a five-file structured state snapshot (cpu_state.json, +// memory.json, kernel.json, vfs.json, config.json, plus manifest.json) to +// `/canary/` at the moment immediately before the first guest PPC +// instruction of the XEX entry_point executes. See +// `xenia-rs/audit-runs/phase-b-state-equivalence/`. +DECLARE_string(phase_b_snapshot_dir); +DECLARE_bool(phase_b_snapshot_and_exit); +DECLARE_bool(phase_b_dump_section_content); + #endif // XENIA_CPU_CPU_FLAGS_H_ diff --git a/src/xenia/cpu/ppc/ppc_hir_builder.cc b/src/xenia/cpu/ppc/ppc_hir_builder.cc index 42d996cba..d25909079 100644 --- a/src/xenia/cpu/ppc/ppc_hir_builder.cc +++ b/src/xenia/cpu/ppc/ppc_hir_builder.cc @@ -34,6 +34,141 @@ DEFINE_bool( "unimplemented PowerPC instruction is encountered.", "CPU"); +// AUDIT-061 — multi-PC branch probe. Parses cvars::audit_61_branch_probe_pcs +// once and exposes a (pc -> trap_id) lookup table. trap_id range [200, 65535]. +// PCs outside the table are not probed. Native side reads g_audit61_pcs[idx]. +#include +#include +namespace xe { +namespace cpu { +namespace audit61 { +constexpr uint16_t kTrapBase = 200; +constexpr size_t kMaxPcs = 32; +static std::vector g_pcs; +static bool g_parsed = false; + +const std::vector& pcs() { + if (!g_parsed) { + g_parsed = true; + const std::string& csv = cvars::audit_61_branch_probe_pcs; + size_t pos = 0; + while (pos < csv.size() && g_pcs.size() < kMaxPcs) { + size_t end = csv.find(',', pos); + std::string tok = csv.substr(pos, end - pos); + // strip whitespace + while (!tok.empty() && (tok.front() == ' ' || tok.front() == '\t')) + tok.erase(tok.begin()); + while (!tok.empty() && (tok.back() == ' ' || tok.back() == '\t')) + tok.pop_back(); + if (!tok.empty()) { + try { + uint32_t v = static_cast(std::stoul(tok, nullptr, 0)); + g_pcs.push_back(v); + } catch (...) { + } + } + if (end == std::string::npos) break; + pos = end + 1; + } + } + return g_pcs; +} + +// Returns trap id for pc, or 0 if pc not in probe set. +uint16_t trap_id_for(uint32_t pc) { + const auto& v = pcs(); + for (size_t i = 0; i < v.size(); ++i) { + if (v[i] == pc) return static_cast(kTrapBase + i); + } + return 0; +} +} // namespace audit61 + +// AUDIT-067 — value-watch. Parses cvars::audit_67_value_watch once, exposes +// values via vals(). Trap codes for matches start at kTrapBase = 250. +namespace audit67 { +constexpr uint16_t kTrapBase = 250; +constexpr size_t kMaxVals = 4; +static std::vector g_vals; +static bool g_parsed = false; + +const std::vector& vals() { + if (!g_parsed) { + g_parsed = true; + const std::string& csv = cvars::audit_67_value_watch; + size_t pos = 0; + while (pos < csv.size() && g_vals.size() < kMaxVals) { + size_t end = csv.find(',', pos); + std::string tok = csv.substr(pos, end - pos); + while (!tok.empty() && (tok.front() == ' ' || tok.front() == '\t')) + tok.erase(tok.begin()); + while (!tok.empty() && (tok.back() == ' ' || tok.back() == '\t')) + tok.pop_back(); + if (!tok.empty()) { + try { + uint32_t v = static_cast(std::stoul(tok, nullptr, 0)); + g_vals.push_back(v); + } catch (...) { + } + } + if (end == std::string::npos) break; + pos = end + 1; + } + XELOGI("AUDIT-067-INIT csv=\"{}\" parsed_count={}", csv, g_vals.size()); + for (size_t i = 0; i < g_vals.size(); ++i) { + XELOGI("AUDIT-067-INIT vals[{}] = 0x{:08X}", i, g_vals[i]); + } + } + return g_vals; +} +} // namespace audit67 + +// PHASE-A hash probe — multi-PC guest probe for recovering the IPFB/IDXD +// name-hash. Parses cvars::phase_a_hash_probe once; trap ids start at 300. +// At each fire the native handler derefs r3 as a guest C-string (the archive +// path being hashed) and logs it alongside r3..r6. Mirrors audit61. +namespace hashprobe { +constexpr uint16_t kTrapBase = 300; +constexpr size_t kMaxPcs = 32; +static std::vector g_pcs; +static bool g_parsed = false; + +const std::vector& pcs() { + if (!g_parsed) { + g_parsed = true; + const std::string& csv = cvars::phase_a_hash_probe; + size_t pos = 0; + while (pos < csv.size() && g_pcs.size() < kMaxPcs) { + size_t end = csv.find(',', pos); + std::string tok = csv.substr(pos, end - pos); + while (!tok.empty() && (tok.front() == ' ' || tok.front() == '\t')) + tok.erase(tok.begin()); + while (!tok.empty() && (tok.back() == ' ' || tok.back() == '\t')) + tok.pop_back(); + if (!tok.empty()) { + try { + g_pcs.push_back(static_cast(std::stoul(tok, nullptr, 0))); + } catch (...) { + } + } + if (end == std::string::npos) break; + pos = end + 1; + } + } + return g_pcs; +} + +uint16_t trap_id_for(uint32_t pc) { + const auto& v = pcs(); + for (size_t i = 0; i < v.size(); ++i) { + if (v[i] == pc) return static_cast(kTrapBase + i); + } + return 0; +} +} // namespace hashprobe +} // namespace cpu +} // namespace xe + namespace xe { namespace cpu { namespace ppc { @@ -174,6 +309,32 @@ bool PPCHIRBuilder::Emit(GuestFunction* function, uint32_t flags) { MaybeBreakOnInstruction(address); + // AUDIT-061: emit a trap before this instruction if it's on the probe + // list. The trap fires BEFORE the cmp/branch HIR emit so the native + // handler observes cr0/cr6 set by the *previous* instruction (the cmp + // that controls this conditional branch). ContextBarrier flushes + // HIR temporaries to PPCContext so the handler reads consistent state. + if (!::xe::cpu::audit61::pcs().empty()) { + uint16_t tid = ::xe::cpu::audit61::trap_id_for(address); + if (tid != 0) { + Comment("--audit_61_branch_probe target"); + ContextBarrier(); + Trap(tid); + } + } + + // PHASE-A hash probe: trap before this instruction so the native handler + // observes r3 (arg string ptr) as set by the caller. ContextBarrier + // flushes HIR temporaries so the handler reads consistent GPRs. + if (!::xe::cpu::hashprobe::pcs().empty()) { + uint16_t tid = ::xe::cpu::hashprobe::trap_id_for(address); + if (tid != 0) { + Comment("--phase_a_hash_probe target"); + ContextBarrier(); + Trap(tid); + } + } + InstrData i; i.address = address; i.code = code; diff --git a/src/xenia/kernel/event_log.cc b/src/xenia/kernel/event_log.cc new file mode 100644 index 000000000..219c2b538 --- /dev/null +++ b/src/xenia/kernel/event_log.cc @@ -0,0 +1,709 @@ +/** + ****************************************************************************** + * Xenia : Xbox 360 Emulator Research Project * + ****************************************************************************** + * Phase A event-log emitter — see event_log.h and schema-v1.md. + ****************************************************************************** + */ + +#include "xenia/kernel/event_log.h" + +#include +#include +#include +#include +#include +#include +#include + +#include "third_party/fmt/include/fmt/format.h" + +#include "xenia/base/cvar.h" +#include "xenia/cpu/ppc/ppc_context.h" +#include "xenia/kernel/kernel.h" +#include "xenia/kernel/kernel_state.h" +#include "xenia/kernel/util/object_table.h" +#include "xenia/kernel/xfile.h" +#include "xenia/kernel/xthread.h" +#include "xenia/memory.h" + +DECLARE_string(phase_a_event_log_path); +DECLARE_bool(kernel_emit_contention); +DECLARE_bool(phase_a_trace_args); +DECLARE_string(phase_a_hash_probe); + +namespace xe { +namespace kernel { +namespace phase_a { + +namespace { + +// Cached enabled state, computed lazily from cvar (cheap fast-path). +std::atomic g_state{0}; // 0=untouched, 1=enabled, 2=disabled +std::FILE* g_file = nullptr; +std::mutex g_file_mu; +std::once_flag g_init_once; + +// Per-thread monotonic event index (key for the diff tool). +// Phase C+15-α: per-tid (not per-host-thread). Multiple host threads +// can emit with tid=0 (boot + XThread bootstrap before guest tid is +// assigned), and a thread_local counter aliased across host threads +// produces duplicate `tid_event_idx` values, breaking the diff tool's +// monotonicity invariant. Use a tid-keyed map guarded by a mutex. +std::unordered_map g_tid_counters; +std::mutex g_tid_counters_mu; + +uint64_t NextTidEventIdx(uint32_t tid) { + std::lock_guard lock(g_tid_counters_mu); + auto& c = g_tid_counters[tid]; + uint64_t v = c; + c = v + 1; + return v; +} + +uint64_t PeekTidEventIdxLocked(uint32_t tid) { + std::lock_guard lock(g_tid_counters_mu); + auto it = g_tid_counters.find(tid); + return it == g_tid_counters.end() ? 0 : it->second; +} + +// Process-start ns for the host_ns field. Captured on first use; debug only. +std::chrono::steady_clock::time_point g_t0; +std::once_flag g_t0_once; + +void EnsureT0() { + std::call_once(g_t0_once, + []() { g_t0 = std::chrono::steady_clock::now(); }); +} + +int64_t HostNsSinceStart() { + EnsureT0(); + auto now = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(now - g_t0) + .count(); +} + +void OpenIfNeeded() { + std::call_once(g_init_once, []() { + const std::string& path = cvars::phase_a_event_log_path; + if (path.empty()) { + g_state.store(2, std::memory_order_release); + return; + } + g_file = std::fopen(path.c_str(), "wb"); + if (!g_file) { + g_state.store(2, std::memory_order_release); + return; + } + g_state.store(1, std::memory_order_release); + // Write the schema header as the first line — synthetic tid=0. + auto header = fmt::format( + "{{\"schema_version\":1,\"engine\":\"canary\",\"kind\":\"schema_version" + "\",\"tid\":0,\"tid_event_idx\":0,\"guest_cycle\":0,\"host_ns\":{},\"" + "deterministic\":true,\"payload\":{{\"version\":1,\"emitter_build\":\"" + "canary-phaseA\"}}}}\n", + HostNsSinceStart()); + std::fwrite(header.data(), 1, header.size(), g_file); + std::fflush(g_file); + }); +} + +uint32_t CurrentTid() { + // Phase C+15-α: AddHandle / RemoveHandle hooks can fire from boot + // code (XEX loader, kernel-state init) BEFORE any XThread exists. + // `XThread::GetCurrentThreadId` asserts in that case. Use the + // safe `TryGetCurrentThread` accessor (returns null instead of + // asserting). Return 0 (synthetic "no-thread" tid) when not in a + // guest thread, matching ours's `scheduler.current == None` + // semantics during boot init. + XThread* t = XThread::TryGetCurrentThread(); + if (!t) { + return 0; + } + return t->guest_object()->thread_id; +} + +void WriteLine(const std::string& line) { + std::lock_guard lock(g_file_mu); + if (!g_file) return; + std::fwrite(line.data(), 1, line.size(), g_file); + std::fputc('\n', g_file); + // Flush every line so a crash mid-boot still produces a useful prefix. + std::fflush(g_file); +} + +// Common-fields prefix. Caller appends `,\"payload\":{...}}`. +// kind, tid, tid_event_idx, guest_cycle=0 (canary has no kernel-layer cycle), +// host_ns, deterministic, engine. +std::string CommonPrefix(const char* kind, uint32_t tid, uint64_t idx, + bool deterministic) { + return fmt::format( + "{{\"schema_version\":1,\"engine\":\"canary\",\"kind\":\"{}\",\"tid\":{}," + "\"tid_event_idx\":{},\"guest_cycle\":0,\"host_ns\":{},\"deterministic\":" + "{}", + kind, tid, idx, HostNsSinceStart(), deterministic ? "true" : "false"); +} + +// Escape a JSON string. Keep it minimal — kernel names are ASCII. +std::string EscapeJson(const char* s) { + if (!s) return "null"; + std::string out; + out.reserve(std::strlen(s) + 2); + for (const char* p = s; *p; ++p) { + unsigned char c = static_cast(*p); + if (c == '\\' || c == '"') { + out.push_back('\\'); + out.push_back(static_cast(c)); + } else if (c == '\n') { + out += "\\n"; + } else if (c == '\r') { + out += "\\r"; + } else if (c == '\t') { + out += "\\t"; + } else if (c < 0x20) { + out += fmt::format("\\u{:04x}", c); + } else { + out.push_back(static_cast(c)); + } + } + return out; +} + +} // namespace + +bool IsEnabled() { + int s = g_state.load(std::memory_order_acquire); + if (s == 0) { + OpenIfNeeded(); + s = g_state.load(std::memory_order_acquire); + } + return s == 1; +} + +uint64_t PeekTidEventIdx() { return PeekTidEventIdxLocked(CurrentTid()); } + +uint64_t ComputeSemanticId(uint32_t create_site_pc, uint32_t creating_tid, + uint64_t tid_event_idx_at_creation, + uint32_t object_type) { + uint8_t bytes[4 + 4 + 8 + 4]; + auto put_u32 = [&](size_t off, uint32_t v) { + bytes[off + 0] = static_cast(v & 0xFF); + bytes[off + 1] = static_cast((v >> 8) & 0xFF); + bytes[off + 2] = static_cast((v >> 16) & 0xFF); + bytes[off + 3] = static_cast((v >> 24) & 0xFF); + }; + auto put_u64 = [&](size_t off, uint64_t v) { + for (int i = 0; i < 8; ++i) + bytes[off + i] = static_cast((v >> (i * 8)) & 0xFF); + }; + put_u32(0, create_site_pc); + put_u32(4, creating_tid); + put_u64(8, tid_event_idx_at_creation); + put_u32(16, object_type); + uint64_t h = 0xCBF29CE484222325ULL; + for (size_t i = 0; i < sizeof(bytes); ++i) { + h ^= bytes[i]; + h *= 0x100000001B3ULL; + } + return h; +} + +void EmitSchemaHeader() { + if (!IsEnabled()) return; + // tid=0, tid_event_idx=0, deterministic=true. NOT consuming the per-tid + // counter (the header is on a synthetic tid 0). + std::string line = fmt::format( + "{{\"schema_version\":1,\"engine\":\"canary\",\"kind\":\"schema_version" + "\",\"tid\":0,\"tid_event_idx\":0,\"guest_cycle\":0,\"host_ns\":{},\"" + "deterministic\":true,\"payload\":{{\"version\":1,\"emitter_build\":\"" + "canary-phaseA\"}}}}", + HostNsSinceStart()); + WriteLine(line); +} + +void EmitImportCall(const char* module_name, uint16_t ordinal, + const char* fn_name) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("import.call", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"module\":\"{}\",\"ord\":{},\"name\":\"{}\"}}}}", + EscapeJson(module_name), ordinal, EscapeJson(fn_name)); + WriteLine(line); +} + +void EmitKernelCall(const char* name) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.call", tid, idx, true); + line += fmt::format(",\"payload\":{{\"name\":\"{}\",\"args\":{{}},\"args_" + "resolved\":{{}}}}}}", + EscapeJson(name)); + WriteLine(line); +} + +// Phase C+10 schema-v1 extension: emit a `kernel.call` event whose +// `args_resolved` field includes a `"path"` entry. The path string is +// the canonical post-prefix-strip form (forward slashes, leading +// device prefix removed). When `path` is null/empty, degrades to the +// existing empty-args_resolved form so output is byte-identical to +// the pre-extension behavior for unknown export names. +void EmitKernelCallWithPath(const char* name, const char* path) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.call", tid, idx, true); + if (path && *path) { + line += fmt::format( + ",\"payload\":{{\"name\":\"{}\",\"args\":{{}},\"args_resolved\":" + "{{\"path\":\"{}\"}}}}}}", + EscapeJson(name), EscapeJson(path)); + } else { + line += fmt::format(",\"payload\":{{\"name\":\"{}\",\"args\":{{}},\"args_" + "resolved\":{{}}}}}}", + EscapeJson(name)); + } + WriteLine(line); +} + +void EmitKernelReturn(const char* name, uint64_t return_value) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.return", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"name\":\"{}\",\"return_value\":{},\"status\":\"0x{:08x}" + "\",\"side_effects\":[]}}}}", + EscapeJson(name), return_value, static_cast(return_value)); + WriteLine(line); +} + +void EmitHandleCreate(uint64_t semantic_id, uint32_t object_type, + uint32_t raw_handle_id, const char* object_name) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("handle.create", tid, idx, true); + if (object_name && *object_name) { + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"object_type\":{}," + "\"object_name\":\"{}\",\"raw_handle_id\":\"0x{:08x}\"}}}}", + semantic_id, object_type, EscapeJson(object_name), raw_handle_id); + } else { + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"object_type\":{}," + "\"object_name\":null,\"raw_handle_id\":\"0x{:08x}\"}}}}", + semantic_id, object_type, raw_handle_id); + } + WriteLine(line); +} + +void EmitHandleDestroy(uint64_t semantic_id, uint32_t raw_handle_id, + uint32_t prior_refcount) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("handle.destroy", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"raw_handle_id\":\"" + "0x{:08x}\",\"prior_refcount\":{}}}}}", + semantic_id, raw_handle_id, prior_refcount); + WriteLine(line); +} + +void EmitThreadCreate(uint64_t semantic_id, uint32_t parent_tid, + uint32_t entry_pc, uint32_t ctx_ptr, uint32_t priority, + uint32_t affinity, uint32_t stack_size, bool suspended) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("thread.create", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"handle_semantic_id\":\"{:016x}\",\"parent_tid\":{}," + "\"entry_pc\":\"0x{:08x}\",\"ctx_ptr\":\"0x{:08x}\",\"priority\":{}," + "\"affinity\":{},\"stack_size\":{},\"suspended\":{}}}}}", + semantic_id, parent_tid, entry_pc, ctx_ptr, priority, affinity, + stack_size, suspended ? "true" : "false"); + WriteLine(line); +} + +void EmitThreadExit(uint32_t exit_code) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("thread.exit", tid, idx, true); + line += fmt::format(",\"payload\":{{\"exit_code\":{}}}}}", exit_code); + WriteLine(line); +} + +void EmitWaitBegin(const uint64_t* handles_semantic_ids, uint32_t count, + int64_t timeout_ns, bool alertable, bool wait_all) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("wait.begin", tid, idx, true); + std::string ids = "["; + for (uint32_t i = 0; i < count; ++i) { + if (i) ids += ","; + ids += fmt::format("\"{:016x}\"", handles_semantic_ids[i]); + } + ids += "]"; + line += fmt::format( + ",\"payload\":{{\"handles_semantic_ids\":{},\"timeout_ns\":{}," + "\"alertable\":{},\"wait_type\":\"{}\"}}}}", + ids, timeout_ns, alertable ? "true" : "false", + wait_all ? "all" : "any"); + WriteLine(line); +} + +void EmitWaitEnd(uint32_t status, uint64_t woken_by_semantic_id_or_zero) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("wait.end", tid, idx, false); + if (woken_by_semantic_id_or_zero) { + line += fmt::format( + ",\"payload\":{{\"status\":\"0x{:08x}\",\"woken_by_semantic_id\":\"" + "{:016x}\",\"wait_duration_cycles\":0}}}}", + status, woken_by_semantic_id_or_zero); + } else { + line += fmt::format( + ",\"payload\":{{\"status\":\"0x{:08x}\",\"woken_by_semantic_id\":null," + "\"wait_duration_cycles\":0}}}}", + status); + } + WriteLine(line); +} + +// ===== Phase C+15-α — Handle semantic ID registry ===== +namespace { +std::unordered_map g_handle_sids; +std::mutex g_handle_sids_mu; +} // namespace + +void RegisterHandleSemanticId(uint32_t raw_handle_id, uint64_t sid) { + if (!IsEnabled()) return; + std::lock_guard lock(g_handle_sids_mu); + g_handle_sids[raw_handle_id] = sid; +} + +uint64_t LookupHandleSemanticId(uint32_t raw_handle_id) { + std::lock_guard lock(g_handle_sids_mu); + auto it = g_handle_sids.find(raw_handle_id); + return it == g_handle_sids.end() ? 0 : it->second; +} + +uint64_t ForgetHandleSemanticId(uint32_t raw_handle_id) { + std::lock_guard lock(g_handle_sids_mu); + auto it = g_handle_sids.find(raw_handle_id); + if (it == g_handle_sids.end()) return 0; + uint64_t sid = it->second; + g_handle_sids.erase(it); + return sid; +} + +uint64_t EmitHandleCreateAuto(uint32_t create_site_pc, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name) { + if (!IsEnabled()) return 0; + uint32_t tid = CurrentTid(); + uint64_t idx_at_creation = PeekTidEventIdxLocked(tid); + uint64_t sid = + ComputeSemanticId(create_site_pc, tid, idx_at_creation, object_type); + RegisterHandleSemanticId(raw_handle_id, sid); + EmitHandleCreate(sid, object_type, raw_handle_id, object_name); + return sid; +} + +void EmitHandleDestroyAuto(uint32_t raw_handle_id, uint32_t prior_refcount) { + if (!IsEnabled()) return; + uint64_t sid = ForgetHandleSemanticId(raw_handle_id); + EmitHandleDestroy(sid, raw_handle_id, prior_refcount); +} + +// ===== Phase C+18 — Shared-global SIDs ===== + +uint64_t ComputeSharedGlobalSemanticId(uint32_t pointer, uint32_t object_type) { + // Reuse the same FNV-1a recipe as `ComputeSemanticId` but with inputs + // chosen to be scheduling-invariant: + // create_site_pc = kSharedGlobalSidMarker (distinguishes from regular SIDs) + // creating_tid = 0 + // tid_event_idx_at_creation = pointer (as u64) + // object_type = object_type + // Matches `event_log.rs::semantic_id_shared_global` byte-for-byte. + return ComputeSemanticId(kSharedGlobalSidMarker, 0, + static_cast(pointer), object_type); +} + +void EmitHandleCreateSharedGlobal(uint32_t pointer, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name) { + if (!IsEnabled()) return; + uint64_t sid = ComputeSharedGlobalSemanticId(pointer, object_type); + RegisterHandleSemanticId(raw_handle_id, sid); + EmitHandleCreate(sid, object_type, raw_handle_id, object_name); +} + +// Phase C+18: per-host-thread flag that the AddHandle hook checks to +// skip its `EmitHandleCreateAuto` call for XObjects synthesized by +// `XObject::GetNativeObject` (a single boolean — the global critical +// region is held across the GetNativeObject body so re-entrancy isn't +// expected). +namespace { +thread_local bool t_in_get_native_object = false; +} // namespace + +void SetInGetNativeObject(bool active) { t_in_get_native_object = active; } +bool IsInGetNativeObject() { return t_in_get_native_object; } + +// ===== Phase D Stage 1 — contention.observed ===== + +void EmitContentionObserved(uint32_t cs_guest_ptr, bool contended) { + // Two-gate fast path: cvar OFF is the default and must be byte-identical + // to pre-Stage-1 canary. The cvar is checked first to short-circuit even + // when the phase A event log itself is enabled (Stage 0/baseline cold + // runs may have event log on but contention emit off). + if (!cvars::kernel_emit_contention) return; + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + uint64_t site_sid = + ComputeSharedGlobalSemanticId(cs_guest_ptr, kObjCriticalSection); + std::string line = CommonPrefix("contention.observed", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"cs_ptr\":\"0x{:08x}\",\"site_sid\":\"{:016x}\"," + "\"contended\":{}}}}}", + cs_guest_ptr, site_sid, contended ? "true" : "false"); + WriteLine(line); +} + +// ── Expansive extraction tracing (game-data RE) ──────────────────────────── +// All gated by `phase_a_trace_args` / `phase_a_hash_probe` (default off), so +// with those unset the JSONL output is byte-identical to the diff-schema form. + +// kernel.call with populated `args` (raw r3..r10) and `args_resolved` +// (currently the resolved file path, when known). `ppc_context` is a +// PPCContext* passed as void* to keep the header free of the PPC include. +void EmitKernelCallArgs(const char* name, void* ppc_context, + const char* resolved_path) { + if (!IsEnabled()) return; + auto* ctx = reinterpret_cast<::xe::cpu::ppc::PPCContext*>(ppc_context); + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("kernel.call", tid, idx, true); + std::string args; + if (ctx) { + args = fmt::format( + "\"r3\":{},\"r4\":{},\"r5\":{},\"r6\":{},\"r7\":{},\"r8\":{},\"r9\":{}," + "\"r10\":{}", + ctx->r[3], ctx->r[4], ctx->r[5], ctx->r[6], ctx->r[7], ctx->r[8], + ctx->r[9], ctx->r[10]); + } + std::string resolved; + if (resolved_path && *resolved_path) { + resolved = fmt::format("\"path\":\"{}\"", EscapeJson(resolved_path)); + } + line += fmt::format( + ",\"payload\":{{\"name\":\"{}\",\"args\":{{{}}},\"args_resolved\":{{{}}}}}}}", + EscapeJson(name), args, resolved); + WriteLine(line); +} + +// file.read — a guest read from an open file handle. `path` is resolved from +// the handle via the object table; `offset` is the requested byte offset. +void EmitFileRead(uint32_t handle, const char* path, uint64_t offset, + uint32_t length, uint32_t buffer_va) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("file.read", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"handle\":\"0x{:08x}\",\"path\":\"{}\",\"offset\":{}," + "\"length\":{},\"buffer_va\":\"0x{:08x}\"}}}}", + handle, EscapeJson(path), offset, length, buffer_va); + WriteLine(line); +} + +// guest.call — fired by the guest-PC hash probe (Tier 3). `arg_str` is r3 +// dereferenced as a guest C-string (the archive path being hashed). +void EmitGuestCall(uint32_t pc, const char* arg_str, uint32_t r3, uint32_t r4, + uint32_t r5, uint32_t r6) { + if (!IsEnabled()) return; + uint32_t tid = CurrentTid(); + uint64_t idx = NextTidEventIdx(tid); + std::string line = CommonPrefix("guest.call", tid, idx, true); + line += fmt::format( + ",\"payload\":{{\"pc\":\"0x{:08x}\",\"arg_str\":\"{}\",\"r3\":\"0x{:08x}\"," + "\"r4\":\"0x{:08x}\",\"r5\":\"0x{:08x}\",\"r6\":\"0x{:08x}\"}}}}", + pc, EscapeJson(arg_str), r3, r4, r5, r6); + WriteLine(line); +} + +} // namespace phase_a + +// Bridge entry points referenced from shim_utils.h. Defined here so the +// template-heavy header does not need to include event_log.h directly. +namespace shim { +namespace phase_a_bridge { + +namespace { + +// Phase C+10: read an OBJECT_ATTRIBUTES* guest address and return the +// raw ANSI_STRING path (trimmed). Empty/null returns std::string(). +// Mirrors ours's `path::object_attributes_raw_name`. +std::string ReadObjectAttributesRawName(uint32_t obj_attrs_ptr) { + if (!obj_attrs_ptr) return std::string(); + auto* ks = ::xe::kernel::KernelState::shared(); + if (!ks) return std::string(); + auto* memory = ks->memory(); + if (!memory) return std::string(); + auto* obj_attrs = + memory->TranslateVirtual<::xe::kernel::X_OBJECT_ATTRIBUTES*>( + obj_attrs_ptr); + if (!obj_attrs) return std::string(); + uint32_t name_ptr = obj_attrs->name_ptr; + if (!name_ptr) return std::string(); + auto* ansi = + memory->TranslateVirtual<::xe::kernel::X_ANSI_STRING*>(name_ptr); + if (!ansi) return std::string(); + uint16_t length = ansi->length; + uint32_t buffer = ansi->pointer; + if (!length || !buffer) return std::string(); + auto* bytes = memory->TranslateVirtual(buffer); + if (!bytes) return std::string(); + std::string raw(bytes, length); + // Strip trailing NULs that some callers include in the byte count. + while (!raw.empty() && raw.back() == '\0') raw.pop_back(); + // Trim whitespace (mirror canary's `string_util::trim`). + auto first = raw.find_first_not_of(" \t\r\n"); + auto last = raw.find_last_not_of(" \t\r\n"); + if (first == std::string::npos) return std::string(); + return raw.substr(first, last - first + 1); +} + +// Phase C+11 — read an `X_FILE_RENAME_INFORMATION` buffer's rename +// target ANSI_STRING. Layout per `info/file.h:79-83` (16 bytes): +// offset 0 be replace_existing +// offset 4 be root_dir_handle +// offset 8 X_ANSI_STRING { u16 Length, u16 MaxLength, u32 Buffer } +// Caller is expected to check `info_length >= 16` before invoking. +// Mirrors ours's `path::file_rename_information_raw_target`. +std::string ReadFileRenameInformationRawTarget(uint32_t info_ptr, + uint32_t info_length) { + if (!info_ptr || info_length < 16) return std::string(); + auto* ks = ::xe::kernel::KernelState::shared(); + if (!ks) return std::string(); + auto* memory = ks->memory(); + if (!memory) return std::string(); + auto* ansi = memory->TranslateVirtual<::xe::kernel::X_ANSI_STRING*>( + info_ptr + 8); + if (!ansi) return std::string(); + uint16_t length = ansi->length; + uint32_t buffer = ansi->pointer; + if (!length || !buffer) return std::string(); + auto* bytes = memory->TranslateVirtual(buffer); + if (!bytes) return std::string(); + std::string raw(bytes, length); + while (!raw.empty() && raw.back() == '\0') raw.pop_back(); + auto first = raw.find_first_not_of(" \t\r\n"); + auto last = raw.find_last_not_of(" \t\r\n"); + if (first == std::string::npos) return std::string(); + return raw.substr(first, last - first + 1); +} + +// Phase C+10/C+11: known path-bearing exports. Returns the empty string +// for any export whose name is not in the set OR whose OBJECT_ATTRIBUTES* +// arg is null. Argument positions verified against canary's +// `xboxkrnl_io.cc` / `xboxkrnl_io_info.cc` signatures. +std::string ResolvePathArg(const char* name, + ::xe::cpu::ppc::PPCContext* ctx) { + if (!name || !ctx) return std::string(); + // r3..r7 only — narrow the dispatch by first char to keep the + // hot-path branch table tight. + if (name[0] != 'N') return std::string(); + // NtQueryFullAttributesFile: r3 = obj_attrs + if (std::strcmp(name, "NtQueryFullAttributesFile") == 0) { + return ReadObjectAttributesRawName(static_cast(ctx->r[3])); + } + // NtOpenSymbolicLinkObject: r4 = obj_attrs + if (std::strcmp(name, "NtOpenSymbolicLinkObject") == 0) { + return ReadObjectAttributesRawName(static_cast(ctx->r[4])); + } + // NtCreateFile, NtOpenFile: r5 = obj_attrs + if (std::strcmp(name, "NtCreateFile") == 0 || + std::strcmp(name, "NtOpenFile") == 0) { + return ReadObjectAttributesRawName(static_cast(ctx->r[5])); + } + // NtSetInformationFile: r5 = info_ptr, r6 = info_length, r7 = info_class. + // Surface the rename target path when info_class==10 + // (XFileRenameInformation). Mirrors ours's C+11 dispatch in + // `crates/xenia-kernel/src/state.rs` call_export. + if (std::strcmp(name, "NtSetInformationFile") == 0 && + static_cast(ctx->r[7]) == 10) { + return ReadFileRenameInformationRawTarget( + static_cast(ctx->r[5]), + static_cast(ctx->r[6])); + } + return std::string(); +} + +} // namespace + +bool Enabled() { return ::xe::kernel::phase_a::IsEnabled(); } +void EmitImportAndCall(const char* module_name, uint16_t ord, + const char* name) { + ::xe::kernel::phase_a::EmitImportCall(module_name, ord, name); + ::xe::kernel::phase_a::EmitKernelCall(name); +} +// Tier 2: for NtReadFile, resolve the handle to its file path (object table) +// and emit a file.read event with the requested byte offset / length / buffer. +// NtReadFile(r3=FileHandle, .., r8=Buffer, r9=Length, r10=ByteOffset*). +void MaybeEmitFileRead(const char* name, ::xe::cpu::ppc::PPCContext* ctx) { + if (!ctx || std::strcmp(name, "NtReadFile") != 0) return; + auto* ks = ::xe::kernel::KernelState::shared(); + if (!ks) return; + auto* memory = ks->memory(); + uint32_t handle = static_cast(ctx->r[3]); + uint32_t buffer = static_cast(ctx->r[8]); + uint32_t length = static_cast(ctx->r[9]); + uint32_t byteoff_ptr = static_cast(ctx->r[10]); + uint64_t offset = 0; + if (byteoff_ptr && memory) { + auto* p = memory->TranslateVirtual<::xe::be*>(byteoff_ptr); + if (p) offset = static_cast(*p); + } + std::string path; + auto file = ks->object_table()->LookupObject<::xe::kernel::XFile>(handle); + if (file) path = file->path(); + ::xe::kernel::phase_a::EmitFileRead(handle, path.c_str(), offset, length, + buffer); +} + +void EmitImportAndCallWithCtx(const char* module_name, uint16_t ord, + const char* name, void* ppc_context) { + ::xe::kernel::phase_a::EmitImportCall(module_name, ord, name); + auto* ctx = reinterpret_cast<::xe::cpu::ppc::PPCContext*>(ppc_context); + std::string path = ResolvePathArg(name, ctx); + if (cvars::phase_a_trace_args) { + // Extraction mode: raw GPR args + resolved path, plus file.read detail. + ::xe::kernel::phase_a::EmitKernelCallArgs( + name, ppc_context, path.empty() ? nullptr : path.c_str()); + MaybeEmitFileRead(name, ctx); + return; + } + if (!path.empty()) { + ::xe::kernel::phase_a::EmitKernelCallWithPath(name, path.c_str()); + } else { + ::xe::kernel::phase_a::EmitKernelCall(name); + } +} +void EmitReturn(const char* name, uint64_t return_value) { + ::xe::kernel::phase_a::EmitKernelReturn(name, return_value); +} +} // namespace phase_a_bridge +} // namespace shim + +} // namespace kernel +} // namespace xe diff --git a/src/xenia/kernel/event_log.h b/src/xenia/kernel/event_log.h new file mode 100644 index 000000000..5845bcd67 --- /dev/null +++ b/src/xenia/kernel/event_log.h @@ -0,0 +1,191 @@ +/** + ****************************************************************************** + * Xenia : Xbox 360 Emulator Research Project * + ****************************************************************************** + * Phase A event-log emitter. Cvar-gated (default off). Schema v1. + * Companion: xenia-rs/audit-runs/phase-a-diff-harness/schema-v1.md + ****************************************************************************** + */ + +#ifndef XENIA_KERNEL_EVENT_LOG_H_ +#define XENIA_KERNEL_EVENT_LOG_H_ + +#include + +namespace xe { +namespace kernel { +namespace phase_a { + +// Object-type codes (must match ours's enum exactly — see schema-v1.md). +enum ObjectType : uint32_t { + kObjUnknown = 0x00, + kObjEvent = 0x01, + kObjMutant = 0x02, + kObjSemaphore = 0x03, + kObjTimer = 0x04, + kObjThread = 0x05, + kObjFile = 0x06, + kObjIoCompletion = 0x07, + kObjModule = 0x08, + kObjEnumState = 0x09, + kObjSection = 0x0A, + kObjNotification = 0x0B, + // Phase D Stage 1: pseudo-type used as the `object_type` input to + // `ComputeSharedGlobalSemanticId` for RTL_CRITICAL_SECTION pointers. CS + // is not a regular `XObject` (it lives as a guest-memory struct, not a + // handle-tabled kernel object), but the `site_sid` field of + // `contention.observed` reuses the shared-global SID recipe so the + // Stage-3 manifest loader can compute the same SID in both engines. + kObjCriticalSection = 0x0C, +}; + +// Fast bool check (default off). Inlinable so we can guard hot paths cheaply. +bool IsEnabled(); + +// Emitted once at startup if enabled (first line of the JSONL). +void EmitSchemaHeader(); + +// FNV-1a 64-bit identity (see schema-v1.md). Both engines compute identically. +uint64_t ComputeSemanticId(uint32_t create_site_pc, uint32_t creating_tid, + uint64_t tid_event_idx_at_creation, + uint32_t object_type); + +// One emit per imported kernel function invocation. Emitted by the export +// trampoline before the kernel.call event. +void EmitImportCall(const char* module_name, uint16_t ordinal, + const char* fn_name); + +// Kernel call entry / return. args/args_resolved are deferred to a later +// phase; v1 emits the name + return value only (sufficient for the diff +// tool to align by sequence). +void EmitKernelCall(const char* name); +// Phase C+10: schema-v1 extension — emit kernel.call whose +// `args_resolved` field carries a resolved `"path"` value (see +// schema-v1.md kernel.call payload). `path == nullptr || *path == '\0'` +// degrades to the existing empty-args_resolved form. +void EmitKernelCallWithPath(const char* name, const char* path); +void EmitKernelReturn(const char* name, uint64_t return_value); + +// Handle lifecycle. raw_handle_id is engine-local; the diff key is the +// FNV-1a semantic id. +void EmitHandleCreate(uint64_t semantic_id, uint32_t object_type, + uint32_t raw_handle_id, const char* object_name); +void EmitHandleDestroy(uint64_t semantic_id, uint32_t raw_handle_id, + uint32_t prior_refcount); + +// Thread create/exit. parent_tid is the caller; entry_pc is the spawned +// thread's first instruction. +void EmitThreadCreate(uint64_t semantic_id, uint32_t parent_tid, + uint32_t entry_pc, uint32_t ctx_ptr, uint32_t priority, + uint32_t affinity, uint32_t stack_size, bool suspended); +void EmitThreadExit(uint32_t exit_code); + +// Wait begin/end. handles_count + handles_semantic_ids array. +void EmitWaitBegin(const uint64_t* handles_semantic_ids, uint32_t count, + int64_t timeout_ns, bool alertable, bool wait_all); +void EmitWaitEnd(uint32_t status, uint64_t woken_by_semantic_id_or_zero); + +// Returns the next per-tid event index (post-increment). Useful for +// `tid_event_idx_at_creation` capture before calling ComputeSemanticId. +uint64_t PeekTidEventIdx(); + +// Phase C+15-α: handle-semantic-ID registry. Maps raw handle id -> +// FNV-1a 64-bit SID assigned at handle creation, so subsequent +// `handle.destroy` / `wait.begin` / etc. events can emit a stable +// cross-engine identity. No-op when event_log is disabled. +void RegisterHandleSemanticId(uint32_t raw_handle_id, uint64_t sid); +uint64_t LookupHandleSemanticId(uint32_t raw_handle_id); +uint64_t ForgetHandleSemanticId(uint32_t raw_handle_id); + +// Convenience: at handle creation time, peek tid_event_idx, compute +// the FNV-1a SID, register it for `raw_handle_id`, and emit a +// `handle.create` event. Returns the SID. `create_site_pc` is set to +// 0 by callers that cannot resolve a guest LR — both engines agree +// on `0` for canonicalization at v1.1. +uint64_t EmitHandleCreateAuto(uint32_t create_site_pc, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name); + +// Convenience: forget mapping + emit `handle.destroy` with the +// previously registered SID. +void EmitHandleDestroyAuto(uint32_t raw_handle_id, uint32_t prior_refcount); + +// Phase C+18: marker constant used as `create_site_pc` in shared-global +// SID computation. Both engines must use exactly this value. See +// schema-v1.md §"Shared-global SIDs". +constexpr uint32_t kSharedGlobalSidMarker = 0xC01AB005; + +// Phase C+18: compute the scheduling-invariant SID for a +// **process-global** kernel dispatcher (canary's +// `XObject::GetNativeObject` lazy-wrap on first guest-thread touch). +// Keyed on `(SHARED_GLOBAL_SID_MARKER, 0, pointer, object_type)` so the +// SID depends only on the object's identity, not on the scheduling order. +uint64_t ComputeSharedGlobalSemanticId(uint32_t pointer, uint32_t object_type); + +// Phase C+18: emit `handle.create` with a scheduling-invariant SID for +// a process-global kernel dispatcher synthesized by +// `XObject::GetNativeObject`. The SID is computed via +// `ComputeSharedGlobalSemanticId(pointer, object_type)` so the same +// dispatcher yields the same SID in both engines regardless of which +// guest thread happens to be the first toucher. `raw_handle_id` is the +// XObject's allocated handle; `pointer` is the guest dispatcher +// (`X_DISPATCH_HEADER*`) pointer (used only to derive the SID). +// +// Caller MUST avoid the regular AddHandle emit for this XObject (set +// the in-flight thread-local marker around the `new XEvent` / +// `new XSemaphore` ctor and have the AddHandle hook short-circuit). +void EmitHandleCreateSharedGlobal(uint32_t pointer, uint32_t object_type, + uint32_t raw_handle_id, + const char* object_name); + +// Phase C+18: thread-local flag indicating the current host thread is +// inside `XObject::GetNativeObject` lazy-wrap, which constructs a new +// XEvent/XSemaphore wrapper for a process-global guest dispatcher. +// `AddHandle` consults this to skip its regular per-thread +// `handle.create` emit; the explicit shared-global emit happens in +// `GetNativeObject` after `StashHandle`. The flag is a single +// host-thread-local bool — re-entrancy is not expected (the global +// critical region is held throughout). +void SetInGetNativeObject(bool active); +bool IsInGetNativeObject(); + +// Phase D Stage 1: emit a `contention.observed` event from +// `RtlEnterCriticalSection_entry` when the spin-loop is exhausted and +// control falls through to `xeKeWaitForSingleObject`. The Stage-2 manifest +// builder filters on `contended=true` and keys on `(tid, tid_event_idx)` +// so the Stage-3 replay loop in ours can park its own `rtl_enter_critical_section` +// at exactly the same per-tid ordinal. +// +// `cs_guest_ptr` is the guest VA of the `X_RTL_CRITICAL_SECTION` (the +// argument to RtlEnterCS). `site_sid` is computed via +// `ComputeSharedGlobalSemanticId(cs_guest_ptr, kObjCriticalSection)` so +// both engines agree on the SID for the same CS pointer. +// +// Gated on `cvars::kernel_emit_contention && IsEnabled()`. Default +// behavior (cvar off) is byte-identical to pre-Stage-1 canary. +void EmitContentionObserved(uint32_t cs_guest_ptr, bool contended); + +// ── Expansive extraction tracing (game-data RE; gated by phase_a_trace_args / +// phase_a_hash_probe, default off) ───────────────────────────────────────── + +// kernel.call with populated `args` (raw r3..r10 from the PPCContext, passed +// as void*) and `args_resolved` (the resolved file path when known). +void EmitKernelCallArgs(const char* name, void* ppc_context, + const char* resolved_path); + +// file.read — a guest read from an open file handle (path resolved from the +// handle via the object table). Enables correlating .pak reads to TOC entries. +void EmitFileRead(uint32_t handle, const char* path, uint64_t offset, + uint32_t length, uint32_t buffer_va); + +// guest.call — emitted by the guest-PC hash probe: `arg_str` is r3 dereferenced +// as a guest C-string (the archive path being hashed). Used to recover the +// custom IPFB/IDXD name-hash by observing (string -> hash) pairs. +void EmitGuestCall(uint32_t pc, const char* arg_str, uint32_t r3, uint32_t r4, + uint32_t r5, uint32_t r6); + +} // namespace phase_a +} // namespace kernel +} // namespace xe + +#endif // XENIA_KERNEL_EVENT_LOG_H_