diff --git a/.gitignore b/.gitignore index 81dc278..69ba2de 100644 --- a/.gitignore +++ b/.gitignore @@ -11,6 +11,11 @@ # logs / debugger dumps *.log cdb_*.txt +# per-launch forensic breadcrumb (btl4main.cpp) + the launch_report.txt it +# replaces -- runtime artifacts, one per machine, never committed +content/lastrun_*.txt +content/launch_report.txt +content/volume.cfg # editor / OS .vs/ diff --git a/context/operator-console.md b/context/operator-console.md index ead8deb..9e49ddb 100644 --- a/context/operator-console.md +++ b/context/operator-console.md @@ -381,7 +381,8 @@ operator control link over a private tunnel (mesh VPN). |---|---| | `content/operator_relay.log` | the relay's own stdout, teed by the GUI. **Truncated at each session start** — so a Start Session destroys the evidence of the wedge it is being used to clear. Copy it first when diagnosing. | | `matchlogs/_` | per-pod match reports, auto-uploaded on route -9 at each clean round end (relay modes only; a mid-round crash loses it) | -| `content/join.log` | the pod's own log; **never** uploaded, only on the player's machine | +| `content/join_YYYYMMDD.log` | the pod's own log — ONE file per day, appended, every session headed by `===== BT411 SESSION … =====`; **never** uploaded, only on the player's machine. Rotation was removed 2026-07-28: two generations used to be deleted by the player's own relaunches, which is how the 2026-07-27 Owens crash stacks were lost. | +| `content/lastrun_.txt` (mode = solo/join/steam/joyconfig) | the launch record (exe's first-breath block + the bat's exit line). Its ABSENCE after a run means the exe never reached WinMain — loader failure or antivirus (Gitea #41). Replaced `launch_report.txt`. | Every relay log line is wall-clock stamped (`_StampedOut`) so post-mortems can measure delays. The GUI's monitor regexes all use `.search()`, so the prefix is transparent to them. diff --git a/docs/OPERATOR_GUIDE.md b/docs/OPERATOR_GUIDE.md index b169044..bd1f2bc 100644 --- a/docs/OPERATOR_GUIDE.md +++ b/docs/OPERATOR_GUIDE.md @@ -241,7 +241,8 @@ not need to ask players to send anything. Exceptions worth knowing: a client that **crashes mid-round** loses its report, and players on **solo** or **Steam** have no relay to upload through. In those cases ask them for -`content\matchlog_*.txt` directly. Their crash log, `content\join.log`, is **never** uploaded — ask +`content\matchlog_*.txt` directly. Their crash log — `content\join_YYYYMMDD.log`, one file per day +holding every session (plus the tiny `content\lastrun_.txt`) — is **never** uploaded — ask for it explicitly when something went wrong on their end. --- diff --git a/game/btl4main.cpp b/game/btl4main.cpp index 19409d3..7ac9db9 100644 --- a/game/btl4main.cpp +++ b/game/btl4main.cpp @@ -562,17 +562,159 @@ int WINAPI WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance, LPSTR lpCmdLine _CrtSetReportMode(_CRT_ERROR, _CRTDBG_MODE_DEBUG); } - // Redirect the engine's std::cout/DEBUG_STREAM to a log file. BT_LOG names the - // file (default btl4.log) -- REQUIRED for multi-instance runs from one cwd - // (instance 2 would truncate instance 1's log). + // Redirect the engine's std::cout/DEBUG_STREAM to a log file. TWO rules, + // in this order (2026-07-28): + // + // BT_LOG SET -> used VERBATIM, append per BT_LOG_APPEND. This is the + // documented multi-instance contract and MUST NOT change: + // mp_a.log/mp_b.log for 2-node runs from one cwd, the + // operator GUI's rotated operator_N.log, and every + // scratchpad/mp_*.sh harness that greps the file it named. + // BT_LOG UNSET -> the exe names a PER-DAY file itself and ALWAYS appends: + // _YYYYMMDD.log. + // + // WHY the per-day file: the launcher used to rotate (del *.old.log, then + // ren *.log *.old.log), keeping only TWO generations. On 2026-07-27 a + // player crashed twice in an Owens, kept playing, and his own relaunches + // deleted both crash sessions before anyone could ask for them -- the + // stacks are gone permanently. A per-day file has no rotation window to + // fall out of. The stem preserves the launcher identity the .bat used to + // supply; every gate below is set before the log opens and is inherited + // across the menu->mission relaunch. + // The STEM identifies which launcher started us. Hoisted out of the naming + // block because the launch record (lastrun_.txt) uses it too: one + // shared lastrun.txt let a second bat's `del` destroy the first launch's + // block, and file the first's exit code under the wrong pid. + char logStem[32]; + lstrcpynA(logStem, "btl4", sizeof(logStem)); + if (getenv("BT_JOYCONFIG")) lstrcpynA(logStem, "joyconfig", sizeof(logStem)); + else if (getenv("BT_STEAM_NET")) lstrcpynA(logStem, "steam", sizeof(logStem)); + else if (getenv("BT_FE_SOLO")) lstrcpynA(logStem, "solo", sizeof(logStem)); + else if (getenv("BT_FE_JOIN") || getenv("BT_RELAY")) lstrcpynA(logStem, "join", sizeof(logStem)); + + char resolvedLog[MAX_PATH]; + int logSelfNamed = 0; + { + const char *env_log = getenv("BT_LOG"); + if (env_log != NULL && *env_log != '\0') + { + lstrcpynA(resolvedLog, env_log, MAX_PATH); + } + else + { + SYSTEMTIME lt; + GetLocalTime(<); // NOT cmd's %DATE%: locale-ordered, and + // on en-US it contains '/' (path chars). + // SIZE ROLL-OVER -- never deletes anything, but keeps each FILE small + // enough to actually send. A playtest evening concatenates into one + // file (4.3 MB from a single session in scratchpad/night5/), and the + // channel this evidence travels through is a chat attachment. Part 0 + // is _YYYYMMDD.log; once it passes the cap the NEXT launch opens + // _YYYYMMDD.1.log, and so on. Checked only at open, so one very + // long session can still overrun -- that is deliberate: never split a + // live session across files. + const DWORD part_max = 8UL * 1024UL * 1024UL; + for (int part = 0; part < 1000; ++part) + { + if (part == 0) + wsprintfA(resolvedLog, "%s_%04d%02d%02d.log", + logStem, (int)lt.wYear, (int)lt.wMonth, (int)lt.wDay); + else + wsprintfA(resolvedLog, "%s_%04d%02d%02d.%d.log", + logStem, (int)lt.wYear, (int)lt.wMonth, (int)lt.wDay, part); + WIN32_FILE_ATTRIBUTE_DATA fad; + if (!GetFileAttributesExA(resolvedLog, GetFileExInfoStandard, &fad)) + break; // does not exist yet -- use it + if (fad.nFileSizeHigh == 0 && fad.nFileSizeLow < part_max) + break; // still room to append + } + logSelfNamed = 1; + } + } + std::ofstream logfile; - // BT_LOG_APPEND=1: keep prior generations' lines (the lobby-loop - // relaunch truncates the shared BT_LOG otherwise -- multi-generation - // forensics need the whole trail). - logfile.open(getenv("BT_LOG") ? getenv("BT_LOG") : "btl4.log", - (getenv("BT_LOG_APPEND") != NULL && *getenv("BT_LOG_APPEND") == '1') + // A self-named day file appends UNCONDITIONALLY -- the default open mode is + // std::ios::out (TRUNCATE), so relying on the caller to pass BT_LOG_APPEND + // would let the second launch of the day erase the morning. (The operator + // GUI's exported bats do not set it and truncate today.) + logfile.open(resolvedLog, + (logSelfNamed + || (getenv("BT_LOG_APPEND") != NULL && *getenv("BT_LOG_APPEND") == '1')) ? (std::ios::out | std::ios::app) : std::ios::out); - std::cout.rdbuf(logfile.rdbuf()); + // If the log cannot be opened, DO NOT silently rebind cout to a dead buffer: + // the header, [boot] and any crash stack would vanish while lastrun still + // claimed a log=. Fall back to a per-pid name, and if even that fails + // leave cout alone so the lines still go somewhere. + if (!logfile.is_open()) + { + char fallback[MAX_PATH]; + wsprintfA(fallback, "%s_pid%u.log", logStem, (unsigned)GetCurrentProcessId()); + logfile.open(fallback, std::ios::out | std::ios::app); + if (logfile.is_open()) + lstrcpynA(resolvedLog, fallback, MAX_PATH); + } + if (logfile.is_open()) + std::cout.rdbuf(logfile.rdbuf()); + + // Pin the RESOLVED name (and append mode) into the environment so the + // menu->mission relaunch inherits it verbatim instead of re-deriving it. + // Without this a session started at 23:50 would re-resolve after midnight + // and split across two files -- the fragmentation this change exists to fix. + // + // _putenv_s, NOT SetEnvironmentVariableA. MSVC's CRT keeps its OWN copy of + // the environment; SetEnvironmentVariableA updates only the Win32 block, so + // a later getenv() IN THIS PROCESS still returns the old value (measured: + // getenv reads NULL immediately after a successful SetEnvironmentVariableA). + // That matters because btl4console.cpp/btl4lobby.cpp resolve the day log via + // getenv("BT_LOG") -- with SetEnvironmentVariableA they silently fell back to + // marshal.log and the fold never happened. _putenv_s updates BOTH the CRT + // copy and the Win32 block, so in-process getenv AND the inherited + // environment of the menu->mission relaunch both see it. + // + if (logSelfNamed) + { + _putenv_s("BT_LOG", resolvedLog); + _putenv_s("BT_LOG_APPEND", "1"); + } + + // SESSION HEADER -- the log must identify ITSELF, because attachments lose + // their filename in transit (Discord renames pasted logs to message.txt; + // most of the 2026-07-27 evidence arrived that way and had to be + // re-identified by hand). It doubles as the session separator inside a + // per-day file, and it puts build+pid ABOVE any [crash] block so the + // btl4+0xNNNN offsets stay matchable to the right PDB. + { + SYSTEMTIME lt; + GetLocalTime(<); + char machine[MAX_COMPUTERNAME_LENGTH + 1] = "?"; + DWORD machine_len = sizeof(machine); + GetComputerNameA(machine, &machine_len); + std::cout << "\n===== BT411 SESSION" + << " build=" << BT_VERSION_FULL // FULL = version + commit hash: + // a never-rotated day file spans + // builds, and btl4+0xNNNN offsets + // are meaningless without the exact + // build to match a PDB against. + // WHO and WHICH BOX -- the operator receives many of these from many + // players at once, often renamed in transit, so a file must be + // attributable from its CONTENTS alone. callsign is the name the + // operator actually knows a player by; user/machine survive even when + // no callsign has been chosen yet (menu, solo, joyconfig). + << " machine=" << machine + << " user=" << (getenv("USERNAME") ? getenv("USERNAME") : "?") + << " callsign=" << (getenv("BT_CALLSIGN") && *getenv("BT_CALLSIGN") + ? getenv("BT_CALLSIGN") : "-") + << " mode=" << logStem + << " pid=" << (unsigned)GetCurrentProcessId() + << " local=" << lt.wYear << "-" + << (lt.wMonth < 10 ? "0" : "") << lt.wMonth << "-" + << (lt.wDay < 10 ? "0" : "") << lt.wDay << " " + << (lt.wHour < 10 ? "0" : "") << lt.wHour << ":" + << (lt.wMinute< 10 ? "0" : "") << lt.wMinute << ":" + << (lt.wSecond< 10 ? "0" : "") << lt.wSecond + << " log=" << resolvedLog + << " =====" << std::endl << std::flush; + } if (getenv("BT_CRASHTEST") != NULL && *getenv("BT_CRASHTEST") == '1') { @@ -590,6 +732,54 @@ int WINAPI WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance, LPSTR lpCmdLine << (getenv("BT_FE_LOOP") ? " (relaunched generation)" : " (first process)") << std::endl << std::flush; + // LAUNCH BREADCRUMB -- replaces launch_report.txt (Gitea #41 forensics). + // The .bat deletes this file before launching and tests for it afterwards: + // PRESENT means the exe reached WinMain, ABSENT means it was blocked before + // any of our code ran (loader failure / antivirus). This REPLACES the old + // "if not exist " probe, which a per-day log silently breaks -- the + // file survives from earlier launches, so the probe could never fire again + // and every healthy run would be reported as blocked. It also records + // which day-log this launch actually wrote to, which the .bat cannot derive + // itself (cmd has no locale-safe date). + // APPEND, never truncate: the .bat deletes this file before launching and + // writes its own "launching" line into it FIRST, so truncating here would + // erase the outside half of the bracket. One file carries the whole launch + // record (bat -> exe -> bat), which is why launch_report.txt is gone. + // PER-STEM name (lastrun_solo.txt, lastrun_join.txt, ...): one shared + // lastrun.txt meant a second launcher's `del` wiped the first launch's block + // and filed its exit code under the wrong pid. Each bat now deletes and + // probes only its OWN record. Self-identifying for the same reason the log + // header is: these arrive from many players, often renamed. + { + SYSTEMTIME lt; + GetLocalTime(<); + char machine[MAX_COMPUTERNAME_LENGTH + 1] = "?"; + DWORD machine_len = sizeof(machine); + GetComputerNameA(machine, &machine_len); + char lastrun_name[MAX_PATH]; + wsprintfA(lastrun_name, "lastrun_%s.txt", logStem); + std::ofstream breadcrumb(lastrun_name, std::ios::out | std::ios::app); + if (breadcrumb.is_open()) + { + breadcrumb << "exe reached WinMain" + << " build=" << BT_VERSION_FULL + << " machine=" << machine + << " user=" << (getenv("USERNAME") ? getenv("USERNAME") : "?") + << " callsign=" << (getenv("BT_CALLSIGN") && *getenv("BT_CALLSIGN") + ? getenv("BT_CALLSIGN") : "-") + << " mode=" << logStem + << " pid=" << (unsigned)GetCurrentProcessId() + << " local=" << lt.wYear << "-" + << (lt.wMonth < 10 ? "0" : "") << lt.wMonth << "-" + << (lt.wDay < 10 ? "0" : "") << lt.wDay << " " + << (lt.wHour < 10 ? "0" : "") << lt.wHour << ":" + << (lt.wMinute < 10 ? "0" : "") << lt.wMinute << ":" + << (lt.wSecond < 10 ? "0" : "") << lt.wSecond + << "\nlog=" << resolvedLog + << "\nargs=" << (lpCmdLine ? lpCmdLine : "") << "\n"; + } + } + // Say so when we had to go looking for content\ -- a player who launched // the exe directly should see WHY their settings appeared where they did. if (gBTCwdFixNote != NULL) diff --git a/game/glass/btl4console.cpp b/game/glass/btl4console.cpp index 9c2ed68..d01d634 100644 --- a/game/glass/btl4console.cpp +++ b/game/glass/btl4console.cpp @@ -16,19 +16,37 @@ #include // -// The marshal logs to its own file (marshal.log in the cwd = content\): -// the engine's DEBUG log stream is single-threaded and this is a worker -// thread. Ordinary printf-file logging, flushed per line. +// The marshal runs on a WORKER thread and the engine's DEBUG log stream is +// single-threaded, so it cannot share std::cout -- it keeps its own FILE*. +// It does, however, target the SAME per-day log file (2026-07-28): btl4main +// pins the resolved name into BT_LOG before any of this runs, so one getenv +// puts the marshal's lines in the file players are asked for, instead of a +// separate marshal.log nobody knows to send. Own handle + own lock + line +// flush; the fallback keeps the old filename if BT_LOG is somehow unset. // static FILE *marshalLogFile = NULL; +static CRITICAL_SECTION marshalLogLock; +static LONG marshalLogLockReady = 0; static void MarshalLog(const char *format, ...) { + if (InterlockedCompareExchange(&marshalLogLockReady, 1, 0) == 0) + { + InitializeCriticalSection(&marshalLogLock); + InterlockedExchange(&marshalLogLockReady, 2); + } + while (InterlockedCompareExchange(&marshalLogLockReady, 2, 2) != 2) + { + Sleep(0); // another thread is initialising + } + EnterCriticalSection(&marshalLogLock); if (marshalLogFile == NULL) { - marshalLogFile = fopen("marshal.log", "at"); + const char *day_log = getenv("BT_LOG"); + marshalLogFile = fopen((day_log && *day_log) ? day_log : "marshal.log", "at"); if (marshalLogFile == NULL) { + LeaveCriticalSection(&marshalLogLock); return; } } @@ -39,6 +57,7 @@ static void fprintf(marshalLogFile, "\n"); fflush(marshalLogFile); va_end(arguments); + LeaveCriticalSection(&marshalLogLock); } // diff --git a/game/glass/btl4lobby.cpp b/game/glass/btl4lobby.cpp index 83cf9b6..05a5cd8 100644 --- a/game/glass/btl4lobby.cpp +++ b/game/glass/btl4lobby.cpp @@ -28,7 +28,11 @@ static void { if (lobbyLogFile == NULL) { - lobbyLogFile = fopen("marshal.log", "at"); // shares the marshal's file + // Same target as MarshalLog (btl4console.cpp): the per-day log whose + // resolved name btl4main pinned into BT_LOG, so lobby lines land in the + // one file players are asked for. Old filename kept as the fallback. + const char *day_log = getenv("BT_LOG"); + lobbyLogFile = fopen((day_log && *day_log) ? day_log : "marshal.log", "at"); if (lobbyLogFile == NULL) { return; diff --git a/players/README.txt b/players/README.txt index 5f1b0c0..b9b419f 100644 --- a/players/README.txt +++ b/players/README.txt @@ -29,7 +29,8 @@ in the join menu (the operator can override it). When a round ends your game AUTOMATICALLY rejoins for the next one (same seat, same mech) -- just wait for the operator's next launch. Close the window to leave for real. -If the game closes unexpectedly, send the operator content\join.log. +If the game closes unexpectedly, send the operator TODAY'S log -- +content\join_YYYYMMDD.log (the NEWEST one) -- plus content\lastrun_join.txt. AFTER A MULTIPLAYER SESSION: the game writes a small match report (content\matchlog__