nfsmw-online/trace_agent/trace_log.h

// Shared logging for trace_agent (see ARM64_TRANSLATION_LAYER.md's "Native
// ARM32 tracing harness" section). Writes every trace line to BOTH logcat
// (for live `adb logcat` monitoring) and an append-only file under the
// app's own private files dir - logcat alone drops lines on long runs
// (ring buffer wraps, and per-process rate limiting kicks in well before a
// "full" trace's real call volume), so the file is the actual source of
// truth for offline analysis.
//
// Also holds a jmethodID/jfieldID -> "Name sig" cache, populated by the
// Get*MethodID/Get*FieldID wrappers in jni_trace.cpp, so the high-volume
// Call*Method/Get*Field/Set*Field wrappers can log a real, readable name
// instead of a bare pointer - the whole point of a "full" trace is being
// able to read it after the fact without cross-referencing every ID by hand.
#pragma once
#include <android/log.h>
#include <cstdio>
#include <cstdarg>
#include <cstring>
#include <mutex>
#include <string>
#include <unordered_map>
#include <time.h>
#include <unistd.h>

namespace trace_agent {

inline FILE*& LogFile() {
    static FILE* f = nullptr;
    return f;
}
inline std::mutex& LogMutex() {
    static std::mutex m;
    return m;
}

inline void InitFileLog(const char* path) {
    // fopen() called OUTSIDE the lock, deliberately: bionic's fopen()
    // internally calls the exported open() symbol, which - since this
    // library is LD_PRELOAD'd - gets re-intercepted by our own open()
    // wrapper in libc_gles_trace.cpp, which itself calls TraceLog(). If
    // LogMutex() were still held at that point, this second, same-thread
    // lock attempt on a non-reentrant std::mutex would deadlock. The
    // reentrancy guard in TraceLog() below is a second, independent layer
    // against the same class of self-interposition recursion.
    FILE* f = fopen(path, "a");
    std::lock_guard<std::mutex> lock(LogMutex());
    if (LogFile()) fclose(LogFile());
    LogFile() = f;
    if (LogFile()) {
        fprintf(LogFile(), "---- trace_agent file log opened: %s ----\n", path);
        fflush(LogFile());
    }
    __android_log_print(ANDROID_LOG_INFO, "TRACE_AGENT",
                         "InitFileLog: %s -> %s", path, LogFile() ? "ok" : "FAILED (fopen)");
}

inline long long NowMs() {
    struct timespec ts;
    clock_gettime(CLOCK_MONOTONIC, &ts);
    return (long long)ts.tv_sec * 1000 + ts.tv_nsec / 1000000;
}

inline bool& InTraceLog() {
    static thread_local bool v = false;
    return v;
}

// 2026-09-18 (ARM64_TRANSLATION_LAYER.md task #39, A9 ground-truth
// comparison): this used to ALSO call __android_log_print() on every line,
// same as the file write. Confirmed live that's actively harmful for a
// "full" trace, not just redundant - the game's own per-frame draw-call
// volume wraps logcat's small ring buffer in well under a second (a
// 95,000+ line `adb logcat -d` dump had already lost every
// glTexImage2D/glDrawElements line from the exact moment under
// investigation) and Android additionally rate-limits/drops a single
// process's log output past a threshold, silently. Neither of those
// problems touch a plain flushed file write. File-only now - the file is
// the one and only source of truth for anything beyond the first instant;
// see InitFileLogOnceSafe (libc_gles_trace.cpp) for where the output path
// comes from. `adb logcat` is still useful for confirming the agent loaded
// at all (see InitFileLog's own one-time __android_log_print), just not
// for the high-volume trace itself anymore.
inline void TraceLog(const char* fmt, ...) {
    // Reentrancy guard: a handful of libc calls this agent itself makes
    // (fopen -> open, etc.) get re-intercepted by our own LD_PRELOAD
    // wrappers (self-interposition), which would otherwise call back into
    // TraceLog from inside TraceLog on the same thread. Drop the nested
    // call rather than log it (or, worse, deadlock on LogMutex() below) -
    // matches the project's general "never intercept indiscriminately"
    // principle: this agent's own bookkeeping calls aren't part of the
    // game's execution trace anyway.
    if (InTraceLog()) return;
    InTraceLog() = true;

    char buf[1024];
    va_list ap;
    va_start(ap, fmt);
    vsnprintf(buf, sizeof(buf), fmt, ap);
    va_end(ap);

    {
        std::lock_guard<std::mutex> lock(LogMutex());
        if (LogFile()) {
            // Flushed every line, not buffered - these investigations
            // routinely end in a crash or an ActivityManager kill, and a
            // buffered-but-unflushed tail is exactly the data most worth
            // having at that point.
            fprintf(LogFile(), "[%lld] [tid=%d] %s\n", NowMs(), gettid(), buf);
            fflush(LogFile());
        }
    }

    InTraceLog() = false;
}

inline std::unordered_map<const void*, std::string>& NameCache() {
    static std::unordered_map<const void*, std::string> m;
    return m;
}
inline std::mutex& NameCacheMutex() {
    static std::mutex m;
    return m;
}

inline void RememberName(const void* id, const char* name, const char* sig) {
    if (!id) return;
    std::string full = name ? name : "?";
    if (sig) {
        full += " ";
        full += sig;
    }
    std::lock_guard<std::mutex> lock(NameCacheMutex());
    NameCache()[id] = std::move(full);
}

inline std::string LookupName(const void* id) {
    if (!id) return "(null)";
    {
        std::lock_guard<std::mutex> lock(NameCacheMutex());
        auto it = NameCache().find(id);
        if (it != NameCache().end()) return it->second;
    }
    char buf[32];
    snprintf(buf, sizeof(buf), "%p", id);
    return buf;
}

} // namespace trace_agent