#include "level_loading.h" #include "level_loading_progress.h" #include "Engine/Vfs/mod_catalog.h" #include "Engine/Core/Hooks/hooks.h" #include "Engine/Core/Log/logging.h" #include "Engine/Core/Debug/trace.h" #include "Engine/Core/Platform/memory.h" #include "Engine/Game/Build/supported_build.h" #include "Engine/Game/World/client_state.h" #include "Engine/Game/World/world_model.h" #include "Engine/Game/Build/addresses.h" #include "Engine/Game/Build/20260929/engine.h" #include "Engine/Game/Build/20260929/level_loading.h" #include "Extension/Boot/exit_watch.h" #include #include #include #include namespace dingosdk { namespace { using logging::Level; using logging::Channel; using namespace addr::level_loading; using Transition = void (*)(std::uintptr_t, std::uint32_t, std::uint32_t); using Disconnect = void (*)(std::uintptr_t, std::uint32_t); using StateRequest = void (*)(std::uintptr_t, std::uint32_t); using memory::read; constexpr auto highest = memory::highest_user_address; using level_logging::Sample; using level_logging::Progress; struct Observer { std::uintptr_t base{}; Transition original{}; Disconnect original_disconnect{}; StateRequest original_request{}; BeforeLevelTransition before_transition{}; std::atomic active{}; std::atomic next_poll{}, dropped{}; bool drops_reported{}; std::mutex mutex; Progress progress; }; Observer& observer() { static auto* value = new Observer; return *value; } void emit(Level level, std::string_view message) { logging::write(level, Channel::level, message); } // Names the mod behind a custom level that is stuck or never arrived, with // what built it and what the mod merge could not use from it, so a hanging // load can be traced to a folder from the log alone. std::string level_hint(std::string_view destination) { try { const auto& catalog = mods::catalog(); const auto* mod = mods::mod_registering(catalog, destination); if (!mod) return {}; std::string text = "; this level comes from mod " + mod->name; if (mod->tool.empty() && mod->version.empty() && mod->built.empty()) text += " (no build info recorded: an older Studio or another tool built it)"; else text += " (built by " + (mod->tool.empty() ? std::string("an unnamed tool") : mod->tool) + (mod->version.empty() ? "" : " " + mod->version) + (mod->built.empty() ? "" : " on " + mod->built) + ")"; if (mod->problems.empty()) { text += "; the mod merge reported no problem with it"; } else { text += "; the mod merge reported: "; constexpr std::size_t shown = 2; for (std::size_t index = 0; index < mod->problems.size() && index < shown; ++index) text += (index ? " | " : "") + mod->problems[index]; if (mod->problems.size() > shown) text += " | and " + std::to_string(mod->problems.size() - shown) + " more in the startup log"; text += "; reinstall the whole mod folder or rebuild it with a current ReSkate Studio"; } return text; } catch (...) { return {}; } } bool snapshot(std::uintptr_t client, Sample& s) { auto& o = observer(); std::uintptr_t vt{}; if (client < 0x10000 || client > highest - 0x440 || !read(client, vt) || vt != o.base + addr::engine::client_vtable || !read(client + 0xc4, s.state) || s.state > 26 || !read(client + 0xc0, s.game_type) || s.game_type > 3) return false; s.client = client; s.queues_known = read(client + 0x120, s.pending) && s.pending <= 0x10000 && read(client + 0x298, s.descriptions) && s.descriptions <= 0x10000; const auto description = read_world_description(GetCurrentProcess(), client + 0x198); if (description.available) { s.destination = description.level; if (!description.start_point.empty()) s.destination += " @ " + description.start_point; if (!description.lm_level.empty()) s.destination += " + " + description.lm_level; if (!description.lm_start_point.empty()) s.destination += " @ " + description.lm_start_point; if (!description.game_mode.empty()) s.destination += "; mode=" + description.game_mode; if (!description.hosted_mode.empty()) s.destination += "; hosted=" + description.hosted_mode; } unsigned after{}; return read(client + 0xc4, after) && after == s.state && read(client, vt) && vt == o.base + addr::engine::client_vtable; } std::chrono::milliseconds since_process_start() noexcept { FILETIME created{}, exited{}, kernel{}, user{}, now{}; if (!GetProcessTimes(GetCurrentProcess(), &created, &exited, &kernel, &user)) return {}; GetSystemTimeAsFileTime(&now); const auto ticks = [](const FILETIME& time) { return (static_cast(time.dwHighDateTime) << 32) | time.dwLowDateTime; }; return std::chrono::milliseconds(ticks(now) > ticks(created) ? (ticks(now) - ticks(created)) / 10000 : 0); } // The time spent in the level now loaded (GetTickCount64 when it became playable, 0 when none // is) and its destination. Under the observer's lock. std::uint64_t session_started{}; std::string session_destination; // The frame pacing of the time spent in a level, for Sentry. Short stays say nothing about its // frame rate. Called with the observer's lock held. void send_level_session(std::uint64_t at) { if (!session_started) return; const auto pacing = trace::take_frame_pacing(); const auto lasted = at >= session_started ? at - session_started : 0; if (lasted >= 10000 && pacing.frames && pacing.total_ns) trace::record("game.level_session", "app.session", std::chrono::milliseconds(lasted), true, {{"destination", session_destination}}, {{"fps_avg", static_cast(pacing.frames) * 1e9 / static_cast(pacing.total_ns)}, {"hitches", static_cast(pacing.hitches)}, {"worst_frame", static_cast(pacing.worst_ns) / 1e6, "millisecond"}}); session_started = 0; } // The player closing the game (exit_watch, on a thread of its own): the level they are in is // sent now, and given a moment to go out. It used to be sent only when the next level began // loading, so a stay that ended with the game closing (the long ones, as often as not) was // never sent. A close the game turns down starts the stay afresh. void send_level_session_on_close() noexcept { try { auto& o = observer(); { std::unique_lock lock(o.mutex, std::defer_lock); for (int tries = 0; tries < 50 && !lock.try_lock(); ++tries) Sleep(10); if (!lock.owns_lock()) return; if (!session_started) return; const auto now = GetTickCount64(); send_level_session(now); session_started = now; } trace::flush(std::chrono::seconds(3)); } catch (...) {} } // Timings for Sentry (Engine/Core/Debug/trace.h), from the same observations as the log: // each load, the launch up to the first playable level, and the frame pacing of the time // spent in a level. Called with the observer's lock held. void trace_progress(const level_logging::Progress& progress, bool was_running, std::uint64_t started, std::uint64_t at) { // A new load ends the level before it. if (!was_running && progress.running) send_level_session(at); // A load that just reached a terminal state; "first" is the one behind the splash screen. if (!was_running || progress.running || progress.started != started || at < started) return; const bool active = progress.state == 13 || progress.state == 21; trace::record("game.level_load", "app.load", std::chrono::milliseconds(at - started), active, {{"destination", progress.destination}, {"first", progress.sequence == 1 ? "true" : "false"}}); if (!active) return; if (progress.sequence == 1) trace::record("game.boot", "app.start", since_process_start()); (void)trace::take_frame_pacing(); session_started = at; session_destination = progress.destination; } bool observe(std::uintptr_t client, unsigned next, unsigned previous, std::uint64_t at, bool exact) noexcept { auto& o = observer(); try { // Never wait on another observer or retain this lock across a native call. std::unique_lock lock(o.mutex, std::try_to_lock); if (!lock.owns_lock()) { ++o.dropped; return false; } Sample sample; sample.at = at; sample.previous = previous; if (!snapshot(client, sample) || (exact && (next > 26 || previous > 26 || sample.state != next))) return false; const auto was_running = o.progress.running; const auto started = o.progress.started; o.progress.observe(sample, exact, &emit); trace_progress(o.progress, was_running, started, sample.at); if (o.dropped.load() && !o.drops_reported) { o.drops_reported = true; emit(Level::warning, "Some level observations were skipped; recorded stage timings may be incomplete."); } return true; } catch (...) { ++o.dropped; return false; } } void transition(std::uintptr_t client, std::uint32_t next, std::uint32_t previous) { const auto incoming_error = GetLastError(); auto& o = observer(); const auto started = GetTickCount64(); // Emit before forwarding so a stuck native handler leaves its stage in the log. const bool observed = observe(client, next, previous, started, true); // Lifecycle cleanup must not depend on the logging observer obtaining its // try-lock. State 24's native handler can unload assets in this same call. if (o.before_transition) o.before_transition(o.base, next); const auto native_started = GetTickCount64(); SetLastError(incoming_error); o.original(client, next, previous); const auto outgoing_error = GetLastError(); const auto elapsed = GetTickCount64() - native_started; if (observed && elapsed >= 1000) { try { std::unique_lock lock(o.mutex, std::try_to_lock); if (lock.owns_lock() && o.progress.client == client) o.progress.returned(next, elapsed, &emit); } catch (...) { ++o.dropped; } } SetLastError(outgoing_error); } bool compatible(std::uintptr_t base) noexcept { if (base < 0x10000 || base > highest - supported_build::game_image_size) return false; IMAGE_DOS_HEADER dos{}; IMAGE_NT_HEADERS64 nt{}; if (!read(base, dos) || dos.e_magic != IMAGE_DOS_SIGNATURE || dos.e_lfanew <= 0 || dos.e_lfanew > 0x100000 || !read(base + dos.e_lfanew, nt) || nt.Signature != IMAGE_NT_SIGNATURE || nt.FileHeader.Machine != IMAGE_FILE_MACHINE_AMD64 || nt.OptionalHeader.SizeOfImage != supported_build::game_image_size) return false; for (const auto& contract : {level_transition_contract, level_transition_caller_contract}) { std::array actual{}; if (!read(base + contract.rva, actual) || actual != contract.bytes) return false; } return true; } std::string native_callers() { const auto& o = observer(); std::array frames{}; const auto count = CaptureStackBackTrace(1, static_cast(frames.size()), frames.data(), nullptr); std::string callers; for (unsigned i = 0; i < count; ++i) { const auto address = reinterpret_cast(frames[i]); if (address >= o.base && address - o.base < supported_build::game_image_size) callers += std::format(" Skate+{:#x}", address - o.base); } return callers; } void request_state(std::uintptr_t client, std::uint32_t next) { auto& o = observer(); const auto incoming_error = GetLastError(); if (next == 14 || next == 22 || next == 24) { try { std::uint32_t previous{}, game_type{}, connection_offset{}, state{}, reason{}; std::uintptr_t context{}, connection{}; read(client + 0xc4, previous); read(client + 0xc0, game_type); if (read(client + 8, context) && context && read(o.base + addr::engine::context_client_connection_offset, connection_offset) && connection_offset < 0x1000000 && read(context + connection_offset, connection) && connection) { read(connection + 0x120, state); read(connection + 0x124, reason); } logging::log(Level::info, Channel::level, "Native level exit requested: {} -> {}, game_type={}, connection={:#x}, state={}, reason={:#x}, callers:{}.", previous, next, game_type, connection, state, reason, native_callers()); } catch (...) {} } SetLastError(incoming_error); o.original_request(client, next); } void disconnect(std::uintptr_t connection, std::uint32_t reason) { auto& o = observer(); const auto incoming_error = GetLastError(); // The normal shutdown reason is uninteresting. Record the origin of an // unsolicited native disconnect before it drops the local hosted world. if (reason != 0x102cbecd) { try { logging::log(Level::warning, Channel::level, "Native connection disconnect: reason={:#x}, connection={:#x}, callers:{}.", reason, connection, native_callers()); } catch (...) {} } SetLastError(incoming_error); o.original_disconnect(connection, reason); } void trace_state_requests() { auto& o = observer(); std::array bytes{}; if (!read(o.base + level_request_contract.rva, bytes) || bytes != level_request_contract.bytes) { emit(Level::warning, "Native level-exit tracing unavailable: function contract differs."); return; } auto* target = reinterpret_cast(o.base + level_request_contract.rva); void* original{}; if (hook_prepare(target, reinterpret_cast(&request_state), &original) != HookOk) { emit(Level::warning, "Native level-exit tracing unavailable: hook preparation failed."); return; } o.original_request = reinterpret_cast(original); if (hook_enable(target) != HookOk) { (void)hook_remove(target); emit(Level::warning, "Native level-exit tracing unavailable: hook could not be enabled."); } } void trace_disconnects() { auto& o = observer(); std::array bytes{}; if (!read(o.base + connection_disconnect_contract.rva, bytes) || bytes != connection_disconnect_contract.bytes) { emit(Level::warning, "Native disconnect tracing unavailable: function contract differs."); return; } auto* target = reinterpret_cast(o.base + connection_disconnect_contract.rva); void* original{}; if (hook_prepare(target, reinterpret_cast(&disconnect), &original) != HookOk) return; o.original_disconnect = reinterpret_cast(original); if (hook_enable(target) != HookOk) { (void)hook_remove(target); emit(Level::warning, "Native disconnect tracing unavailable: hook could not be enabled."); } } } bool start_level_loading_logging(std::uintptr_t base, BeforeLevelTransition before_transition) noexcept { try { auto& o = observer(); if (o.active.load()) return true; if (!compatible(base)) { emit(Level::warning, "Native level logging contract did not match; using sampled loading messages."); return false; } o.base = base; o.before_transition = before_transition; exit_watch::when_closing(&send_level_session_on_close); auto* target = reinterpret_cast(base + level_transition_contract.rva); void* original{}; auto status = hook_prepare(target, reinterpret_cast(&transition), &original); if (status == HookOk) { o.original = reinterpret_cast(original); status = hook_enable(target); if (status != HookOk) { const auto failure = hook_last_failure(); logging::log(Level::warning, Channel::level, "Native level logging hook failed: status={}, operation={}, thread={}; using sampled loading messages.", static_cast(status), failure.operation, failure.thread_id); (void)hook_remove(target); return false; } } else { logging::log(Level::warning, Channel::level, "Native level logging hook preparation failed: {}; using sampled loading messages.", static_cast(status)); return false; } o.progress.hint = &level_hint; o.active.store(true); trace_disconnects(); trace_state_requests(); emit(Level::info, "Native level-loading stage logging enabled."); return true; } catch (...) { return false; } } std::string last_level_destination() noexcept { try { auto& o = observer(); std::unique_lock lock(o.mutex, std::try_to_lock); if (!lock.owns_lock()) return {}; return o.progress.destination; } catch (...) { return {}; } } bool level_content_active() noexcept { try { auto& o = observer(); std::unique_lock lock(o.mutex, std::try_to_lock); return lock.owns_lock() && o.progress.seen && (o.progress.state == 13 || o.progress.state == 21); } catch (...) { return false; } } std::string custom_level_hint(std::string_view destination) noexcept { return level_hint(destination); } std::string custom_level_notice(std::string_view destination) noexcept { try { const auto* mod = mods::mod_registering(mods::catalog(), destination); if (!mod) return {}; std::string text = "It comes from mod " + mod->name; text += mod->problems.empty() ? ", which the mod merge reported no problem with." : ", which the mod merge could not use in full. Reinstall the whole mod folder, or rebuild it " "with a current ReSkate Studio."; return text + " Details are in ReSkate.log."; } catch (...) { return {}; } } void poll_level_loading(std::uintptr_t client) noexcept { const auto error = GetLastError(); auto& o = observer(); const auto now = GetTickCount64(); auto next = o.next_poll.load(); if (o.active.load() && now >= next && o.next_poll.compare_exchange_strong(next, now + 500)) (void)observe(client, 26, 26, now, false); SetLastError(error); } }