90CNServer/client-patch/90CN_digest_trace.cpp

// 90CN_digest_trace.cpp —— 章节过场（op1378 / story digest）客户端侧**只读**日志。
//
// 背景：服务端能证明它把 op1378 发出去了（日志事件
// game-current-story-digest-last-level-send 带 last_level），但现象是
// 「完成开区任务当次不播，小退重登才播」。要判断卡在哪一侧必须先确认：
//
//   1. 开区任务完成那一刻客户端**有没有收到** op1378、值是多少；
//   2. 它相对场景重建包 op24 是前是后。
//
// 实现：不新增 hook，只在补丁**生产环境实际安装**的 class0 派发代理
// （ProxyTownCopresenceClass0Dispatch）入口读一下已经到手的包结构并写日志。
// 不改行为、不改寄存器现场，全部包在 __try/__except 里。
//
// class0 包布局（与 CacheCurrentCharacterStatsFromClass0Packet 一致）：
//   bytes[0]      = class（0）
//   bytes[1..2]   = opcode（u16 LE）
//   bytes[3..6]   = packetLength（u32 LE）
//   bytes[16..]   = body，长度 = packetLength - 16
//
// 诊断策略：前 kGenericLogLimit 个 class0 包**全部**记一行（含 opcode/长度），
// 用来确认布局与是否真的从这里过；op1378 与 op24 则完全不过滤、始终记录。
#include "90CN_digest_trace.h"

#include <windows.h>
#include <stdio.h>
#include <stdint.h>
#include <string.h>

namespace
{
constexpr unsigned short kStoryDigestOpcode = 1378; // 0x0562
constexpr unsigned short kSceneTransitionOpcode = 24;
constexpr long kGenericLogLimit = 400;

volatile LONG g_totalPackets = 0;
volatile LONG g_digestCount = 0;
volatile LONG g_sceneCount = 0;
volatile LONG g_readyLogged = 0;
bool g_logPathReady = false;
char g_logPath[MAX_PATH] = {};

void EnsureLogPath()
{
    if (g_logPathReady) return;
    g_logPathReady = true;
    char modulePath[MAX_PATH] = {};
    HMODULE self = nullptr;
    if (GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS |
            GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT,
            reinterpret_cast<LPCSTR>(&EnsureLogPath), &self) && self &&
        GetModuleFileNameA(self, modulePath, MAX_PATH))
    {
        char* slash = strrchr(modulePath, '\\');
        if (slash)
        {
            slash[1] = '\0';
            sprintf_s(g_logPath, "%s90CN_digest.log", modulePath);
            return;
        }
    }
    strcpy_s(g_logPath, "90CN_digest.log");
}

void WriteLine(const char* text)
{
#ifdef DNF90_SILENT_LOG
    (void)text; return;
#endif
    if (!text) return;
    EnsureLogPath();
    SYSTEMTIME st;
    GetLocalTime(&st);
    FILE* file = nullptr;
    if (fopen_s(&file, g_logPath, "a") == 0 && file)
    {
        fprintf(file, "%02d:%02d:%02d.%03d  %s\n",
            st.wHour, st.wMinute, st.wSecond, st.wMilliseconds, text);
        fclose(file);
    }
}
}

namespace cn90
{
void LogClass0CutscenePacket(const unsigned char* bytes)
{
    if (!bytes) return;

    if (InterlockedCompareExchange(&g_readyLogged, 1, 0) == 0)
        WriteLine("digest trace ready: class0 packet logging active");

    const unsigned short opcode =
        *reinterpret_cast<const unsigned short*>(bytes + 1);
    const unsigned int packetLength =
        *reinterpret_cast<const unsigned int*>(bytes + 3);
    if (packetLength < 16 || packetLength > 0x100000) return;
    const unsigned int bodyLength = packetLength - 16;

    if (opcode == kStoryDigestOpcode)
    {
        unsigned int lastLevel = 0;
        if (bodyLength >= 4)
            lastLevel = *reinterpret_cast<const unsigned int*>(bytes + 16);
        char text[256] = {};
        sprintf_s(text, "op1378 story-digest received body_len=%u last_level=%u (digest#%ld)",
            bodyLength, lastLevel, static_cast<long>(InterlockedIncrement(&g_digestCount)));
        WriteLine(text);
        return;
    }
    if (opcode == kSceneTransitionOpcode)
    {
        char text[224] = {};
        sprintf_s(text, "op24 scene-transition received body_len=%u (scene#%ld)",
            bodyLength, static_cast<long>(InterlockedIncrement(&g_sceneCount)));
        WriteLine(text);
        return;
    }

    // 诊断：前若干个包全记，确认布局与流量确实经过这里。
    const long total = InterlockedIncrement(&g_totalPackets);
    if (total <= kGenericLogLimit)
    {
        char text[192] = {};
        sprintf_s(text, "class0 opcode=%u body_len=%u (packet#%ld)",
            static_cast<unsigned>(opcode), bodyLength, total);
        WriteLine(text);
    }
}

void LogAviOpen(const char* path, const char* callerRvas)
{
    char text[768] = {};
    sprintf_s(text, "avi-open path=%s client_frames=%s",
        path ? path : "(null)", (callerRvas && callerRvas[0]) ? callerRvas : "(none)");
    WriteLine(text);
}

void LogMovieEntry(unsigned retRva, unsigned ecx, unsigned edx,
    unsigned arg1, const char* s1, unsigned arg2, const char* s2,
    unsigned arg3, const char* s3)
{
    char text[900] = {};
    sprintf_s(text,
        "movie-fn-entry ret_rva=0x%08X ecx=0x%08X edx=0x%08X "
        "arg1=0x%08X[%s] arg2=0x%08X[%s] arg3=0x%08X[%s]",
        retRva, ecx, edx,
        arg1, (s1 && s1[0]) ? s1 : "",
        arg2, (s2 && s2[0]) ? s2 : "",
        arg3, (s3 && s3[0]) ? s3 : "");
    WriteLine(text);
}

void LogMovieInvoke(unsigned fnRva, unsigned thisPtr, const char* path, int willCall)
{
    char text[640] = {};
    sprintf_s(text, "movie-invoke fn_rva=0x%08X this=0x%08X will_call=%d path=%s",
        fnRva, thisPtr, willCall, (path && path[0]) ? path : "(none)");
    WriteLine(text);
}

void LogMovieChain(const char* chain)
{
    char text[768] = {};
    sprintf_s(text, "movie-call-chain %s", (chain && chain[0]) ? chain : "(none)");
    WriteLine(text);
}

void LogMovieVtable(unsigned object, unsigned vtable, const char* slots)
{
    char text[820] = {};
    sprintf_s(text, "movie-vtable this=0x%08X vtbl=0x%08X %s", object, vtable,
        (slots && slots[0]) ? slots : "(none)");
    WriteLine(text);
}

void LogMovieStack(const char* frames)
{
    char text[1640] = {};
    sprintf_s(text, "movie-stack %s", (frames && frames[0]) ? frames : "(none)");
    WriteLine(text);
}

void LogMovieOpen(unsigned retRva, unsigned thisPtr, unsigned argPtr,
    const char* pathText, const char* stackText)
{
    char text[1200] = {};
    sprintf_s(text, "movie-open ret=0x%08X this=0x%08X arg=0x%08X path=\"%s\" stack=%s",
        retRva, thisPtr, argPtr,
        (pathText && pathText[0]) ? pathText : "",
        (stackText && stackText[0]) ? stackText : "(none)");
    WriteLine(text);
}

void LogMoviePlay(unsigned retRva, unsigned thisPtr, const char* stackText)
{
    char text[1024] = {};
    sprintf_s(text, "movie-play ret=0x%08X this=0x%08X stack=%s",
        retRva, thisPtr, (stackText && stackText[0]) ? stackText : "(none)");
    WriteLine(text);
}

void LogMovieRender(long count, unsigned thisPtr, unsigned retRva, const char* stackText)
{
    char text[1024] = {};
    sprintf_s(text, "movie-render #%ld this=0x%08X ret=0x%08X stack=%s",
        count, thisPtr, retRva, (stackText && stackText[0]) ? stackText : "(none)");
    WriteLine(text);
}

void LogStoryDigestTraceReady()
{
    WriteLine("digest trace module loaded");
}
}