From 1777d5a62e6332c63a156d2d11eee6285ed9849e Mon Sep 17 00:00:00 2001 From: Joe DiPrima Date: Tue, 28 Jul 2026 10:33:07 -0500 Subject: [PATCH] one log per day, and every log says who it sent it -- rotation was eating the crash stacks Conn Man crashed twice in an Owens on 2026-07-27, kept playing, and by the time we asked for his logs they no longer existed. Not a mystery: every launcher did if exist content\X.old.log del content\X.old.log if exist content\X.log ren content\X.log X.old.log which keeps TWO generations. He relaunched more than twice, so his own bat deleted both crash sessions. The player who crashes is exactly the player who relaunches immediately, so the retention window was aimed at the wrong case. THE LOG. BT_LOG set still means "use this path verbatim" -- that contract is load-bearing (mp_a.log/mp_b.log for 2-node runs from one cwd, btoperator's operator_N.log, every scratchpad/mp_*.sh that greps the file it named) and is untouched. Only when BT_LOG is UNSET does the exe now name the file itself: content\_YYYYMMDD.log, appended, one per day, no rotation window to fall out of. The stem (solo/join/steam/joyconfig) comes from the gates the bat already sets, so solo still cannot overwrite the MULTIPLAYER log. Self-named files append UNCONDITIONALLY. The default open mode is ios::out -- TRUNCATE -- and the operator GUI's exported bats never set BT_LOG_APPEND, so they were truncating already; leaving append implicit would have let the second launch of the day erase the morning. IDENTITY, because these arrive from many players at once and Discord renames half of them to message.txt (most of the night-5 evidence had to be re-identified by hand): ===== BT411 SESSION build=4.11.603 (d64d75f+) machine=... user=... callsign=Conn Man mode=solo pid=13192 local=... log=... ===== Also the session separator inside a per-day file, and it puts build+hash ABOVE any [crash] block so btl4+0xNNNN offsets stay matchable to a PDB across builds. SIZE. Never delete, but stay sendable: past 8 MB the next launch rolls to _YYYYMMDD.1.log. Checked only at open, so a live session is never split. CONSOLIDATION. launch_report.txt is gone, folded into lastrun_.txt (one launch record: the exe appends its block at first breath, the bat appends the exit line). Per-stem because one shared lastrun.txt let a second launcher's `del` destroy the first launch's block. Its ABSENCE after a run is now the #41 "never reached WinMain" probe -- the old "if not exist X.log" test cannot work against a per-day file, which survives earlier launches, and would have reported every healthy run as blocked by antivirus. marshal.log folded into the day log too; it keeps its own handle and gained a CRITICAL_SECTION because it runs on a worker thread while the engine log stream is single-threaded. play_steam.bat gained a launch bracket it never had -- which is why a Steam player killed before WinMain previously left no evidence at all. _putenv_s, not SetEnvironmentVariableA, to pin the resolved name: MSVC's CRT keeps its own environment copy, so getenv() in-process does NOT see a SetEnvironmentVariableA write (measured). btl4console/btl4lobby resolve the day log via getenv, so with the Win32-only call they silently fell back to marshal.log and the fold never happened. logfile.open() is now checked -- a failed open used to rebind cout to a dead buffer, silently dropping the header, [boot] and any crash stack while lastrun still claimed log=. Verified: append across sessions with distinct pids, crash block landing under its own header, BT_LOG verbatim unmangled, an inherited BT_LOG cleared by the bats, roll-over at 8 MB, and both forensic verdicts (exe ran / exe blocked). Console auto-retrieval is unaffected -- it uploads the matchlog, a different file, and a crashed round never reaches the upload call anyway. Known gaps, deliberately not in this commit: the setlocal hoist for gate leakage when two bats share one console (dev-only), and btoperator's exported bats still lack the lastrun bracket -- do not press Export on a shipped zip. Co-Authored-By: Claude Opus 5 (1M context) --- .gitignore | 5 + context/operator-console.md | 3 +- docs/OPERATOR_GUIDE.md | 3 +- game/btl4main.cpp | 208 ++++++++++++++++++++++++++++++++++-- game/glass/btl4console.cpp | 27 ++++- game/glass/btl4lobby.cpp | 6 +- players/README.txt | 22 +++- players/join.bat | 25 +++-- players/join_lan.bat | 25 +++-- players/joyconfig.bat | 32 +++--- players/play_solo.bat | 59 ++++++---- players/play_steam.bat | 36 +++++-- tools/btoperator.py | 19 ++-- 13 files changed, 384 insertions(+), 86 deletions(-) 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__