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\<stem>_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
<stem>_YYYYMMDD.1.log. Checked only at open, so a live session is never split.
CONSOLIDATION. launch_report.txt is gone, folded into lastrun_<stem>.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=<name>.
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) <noreply@anthropic.com>
This commit is contained in:
Joe DiPrima
co-authored by
Claude Opus 5
Claude Opus 5
parent
d64d75fcf7
commit
1777d5a62e
+199
-9
@@ -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:
|
||||
// <stem>_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_<stem>.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 <stem>_YYYYMMDD.log; once it passes the cap the NEXT launch opens
|
||||
// <stem>_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=<name>. 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 <log>" 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)
|
||||
|
||||
Reference in New Issue
Block a user