diff --git a/runtime/dispatch.c b/runtime/dispatch.c index 89a460b5..0258de91 100644 --- a/runtime/dispatch.c +++ b/runtime/dispatch.c @@ -103,6 +103,7 @@ int rt_ending_enter(void) { static void fatal_end(int code, const char *fmt, va_list ap) __attribute__((noreturn)); static void fatal_end(int code, const char *fmt, va_list ap) { if (!rt_ending_enter()) plat_terminate(code); // a fatal error inside this thread's own report: no second one + rt_log_ending(); // the report reaches the log file past its cap (main.c log_sink) rt_log_sync(); // main.c: the lines queued for the log thread, then these, written here rt_log_raw("FATAL: ", 7); rt_vlogf(fmt, ap); diff --git a/runtime/main.c b/runtime/main.c index b8996ea4..54d81e7a 100644 --- a/runtime/main.c +++ b/runtime/main.c @@ -63,11 +63,13 @@ unsigned rt_trace; // (NX2NAVI_TRACE can write that much). Lines from before log_open wait in a static buffer: mem_init runs first so that // nothing else lands in the guest address space, and an earlier open would put the CRT's heap there. // The end of the run still reaches a file past its cap: once the process is ending (rt_log_ending at the start of an -// orderly end, gfx_present.c rt_exit_begin, and of the frame-time summary, perf.c perf_summary_flush; rt_log_sync at a -// fatal error and in the crash report), up to LOG_END_RESERVE more bytes are written, counted on their own. A +// orderly end, gfx_present.c rt_exit_begin, of the frame-time summary, perf.c perf_summary_flush, of a fatal error, +// dispatch.c fatal_end, of the crash report, crash_handler, of the lost device's watchdog, vk_device.c lost_wait_exit, +// and in plat_exit, log_sync_ending), up to LOG_END_RESERVE more bytes are written, counted on their own. A // trace = perf session reaches the cap in about 90 minutes, and every line after it, the exit summary, "frametime: // exit", the stutter map and FATAL lines included, went to stderr only, which a game started from the launcher or -// Explorer does not keep. +// Explorer does not keep. rt_log_sync alone does not open the reserve: a bug capture calls it in play +// (bugcap.c write_log_tail), and the play's lines after it would fill the reserve before the end came. #define LOG_KEEP 5 #define LOG_CAP (64ull << 20) #define LOG_END_RESERVE (4ull << 20) @@ -79,8 +81,8 @@ static char g_log_early[32768]; static size_t g_log_early_n; static uint64_t g_log_bytes; -// stderr's writes (log_sink). g_log_final: rt_log_sync has run, so the process is ending: an exit, a fatal error or a -// crash report. +// stderr's writes (log_sink). g_log_final: rt_log_sync has run: an exit, a fatal error, a crash report or a bug +// capture (bugcap.c). static PlatMutex g_err_lock = PLAT_MUTEX_INIT; static volatile int32_t g_log_final; static volatile int32_t g_log_ending; // rt_log_ending ran: the process is ending @@ -106,7 +108,7 @@ static void log_sink(const char *p, size_t n) { "but for the lines of its end\n"; plat_append_write(g_log_file, cut, sizeof cut - 1); } - if (__atomic_load_n(&g_log_ending, __ATOMIC_ACQUIRE) || __atomic_load_n(&g_log_final, __ATOMIC_ACQUIRE)) { + if (__atomic_load_n(&g_log_ending, __ATOMIC_ACQUIRE)) { uint64_t t = __atomic_fetch_add(&g_log_tail, n, __ATOMIC_RELAXED); if (!t) { static const char end[] = "[host] log: the end of the run follows; the lines between the cap and it " @@ -132,6 +134,12 @@ void rt_log_sync(void) { logq_sync(); } +// plat_exit's first step in a game run (plat_exit_hook): the process ends here, so its last lines reach the file. +static void log_sync_ending(void) { + rt_log_ending(); + rt_log_sync(); +} + // The console window was closed, or Ctrl+C or Ctrl+Break pressed in it (platform.h plat_console_setup): the end of a // closed game window, which writes the settings, the caches and the saves and logs the exit (gfx_present.c // gfx_window_closed). Left to Windows, a closed console ended the process with nothing saved. @@ -227,7 +235,7 @@ static void log_open(int game) { // A game run writes its log from the log thread (logq.c), whether the lines go to a log file or to stderr alone. const char *e = cfg_get("NX2NAVI_LOG_ASYNC"); if (!game || (e && !strcmp(e, "0"))) return; - plat_exit_hook = rt_log_sync; + plat_exit_hook = log_sync_ending; if (logq_async()) rt_log("log: lines are written by a thread of their own (NX2NAVI_LOG_ASYNC)"); else rt_log("log: no log thread; every line is written by the thread that logs it"); } @@ -366,6 +374,7 @@ static void crash_handler(const PlatCrash *x) { // shared with the fatal error's end (dispatch.c rt_ending_enter): another thread's fault or fatal error waits there // while this report is written; a fault inside this thread's own report ends the process at once if (!rt_ending_enter()) plat_exit(71); + rt_log_ending(); // the report reaches the log file past its cap (log_sink) if (__atomic_load_n(&mode_done, __ATOMIC_ACQUIRE) && x->module) { rt_log("exit: %s (%#x) in %s while the process was ending, after its work was done and saved%s: the run ends " "with its own code %d", x->what, x->code, *x->module ? x->module : "code outside every module", diff --git a/runtime/vk_device.c b/runtime/vk_device.c index 726d76c4..afc29a87 100644 --- a/runtime/vk_device.c +++ b/runtime/vk_device.c @@ -880,6 +880,7 @@ static void lost_wait_exit(void *arg) { int watchdog = arg != NULL; for (int t = 0; t < LOST_EXIT_MS + (watchdog ? 0 : 2000); t += 50) plat_sleep_ms(50); if (watchdog) { + rt_log_ending(); // its line reaches the log file past its cap (main.c log_sink) rt_log_sync(); // the queue's locks only tried (bounded): their holder may be the thread that hangs rt_log("vk: the end of the run did not finish in %d s; ending it", LOST_EXIT_MS / 1000); } diff --git a/tests/fatal_exit_check.c b/tests/fatal_exit_check.c index 4c40d9f8..256d6b8f 100644 --- a/tests/fatal_exit_check.c +++ b/tests/fatal_exit_check.c @@ -32,6 +32,7 @@ extern const IMAGE_TLS_DIRECTORY _tls_used; const void *volatile keep_tls = &_tls_used; // ---- the runtime fatal_end reaches +void rt_log_ending(void) {} void rt_log_sync(void) {} void rt_log_raw(const char *p, size_t n) { DWORD w; diff --git a/tests/log_cap_check.py b/tests/log_cap_check.py index 03686636..2c95b2a7 100644 --- a/tests/log_cap_check.py +++ b/tests/log_cap_check.py @@ -1,8 +1,9 @@ """The log file's cap and the end of the run (runtime/main.c log_sink): past the cap ordinary lines are dropped, with -one line that says so; once the process is ending (rt_log_ending, or rt_log_sync at a fatal error and in the crash -report) its lines are still written, after one line that says the end follows, up to a reserve of their own, however -much was dropped before. Builds log_sink with a small cap and reserve against stand-ins for the file and stderr. No -game files. +one line that says so; once the process is ending (rt_log_ending, which a fatal error and the crash report call before +rt_log_sync) its lines are still written, after one line that says the end follows, up to a reserve of their own, +however much was dropped before. rt_log_sync alone (a bug capture in play, runtime/bugcap.c write_log_tail) does not +open the reserve. Builds log_sink with a small cap and reserve against stand-ins for the file and stderr, and checks +statically that every end that syncs the log marks it as ending first. No game files. Usage: python tests/log_cap_check.py [path to clang]""" import os @@ -79,18 +80,31 @@ static int line(const char *tag, int i) { // returns the line's length return n; } int main(int argc, char **argv) { - int fails = 0, how = argc > 1 && !strcmp(argv[1], "sync"); - int play_n = 0, end_n = 0; + // ending: rt_log_ending (an orderly end); fatal: rt_log_ending, then rt_log_sync (a fatal error, the crash report); + // capture: rt_log_sync in play (a bug capture), more play, then rt_log_ending + const char *how = argc > 1 ? argv[1] : "ending"; + int fails = 0, play_n = 0, end_n = 0; for (int i = 0; i < 1000; i++) play_n = line("play", i); // 35,000 bytes, many times the cap - size_t before_end = file_n; int play = count("play "), cut = count("reached 64 MiB"); - if (how) rt_log_sync(); - else rt_log_ending(); + if (!strcmp(how, "capture")) { + rt_log_sync(); + for (int i = 0; i < 1000; i++) line("more", i); + int more = count("more "), early = count("the end of the run follows"); + printf("capture: after rt_log_sync in play %d of 1000 play lines in the file, the end's line %d time(s)\n", more, + early); + if (more || early) printf("FAIL: rt_log_sync alone opened the end's reserve\n"), fails++; + } + size_t before_end = file_n; + if (strcmp(how, "fatal")) { + rt_log_ending(); + } else { + rt_log_ending(); + rt_log_sync(); + } for (int i = 0; i < 100; i++) end_n = line("last", i); // 3,400 bytes, more than the reserve int end = count("last "), follows = count("the end of the run follows"); - printf("%s: %d play lines in the file, the cut line %d time(s); after %s %d end lines, the line before them %d " - "time(s); the file %zu bytes (cap %llu, reserve %llu)\n", how ? "rt_log_sync" : "rt_log_ending", play, cut, - how ? "rt_log_sync" : "rt_log_ending", end, follows, file_n, LOG_CAP, LOG_END_RESERVE); + printf("%s: %d play lines in the file, the cut line %d time(s); %d end lines, the line before them %d time(s); the " + "file %zu bytes (cap %llu, reserve %llu)\n", how, play, cut, end, follows, file_n, LOG_CAP, LOG_END_RESERVE); if (play != (int)(LOG_CAP / play_n) || cut != 1) printf("FAIL: lines past the cap\n"), fails++; if (follows != 1 || end != (int)(LOG_END_RESERVE / end_n)) printf("FAIL: the end's lines\n"), fails++; if (file_n - before_end > LOG_END_RESERVE + 200) printf("FAIL: past the reserve\n"), fails++; @@ -99,6 +113,37 @@ int main(int argc, char **argv) { ''' +def static_checks(): + """Every end that syncs the log marks the process as ending first, so its lines reach the file past the cap.""" + bad = 0 + rt = ROOT / 'runtime' + ends = [('main.c', 'static void crash_handler(const PlatCrash *x)'), + ('main.c', 'static void log_sync_ending(void)'), + ('dispatch.c', 'static void fatal_end(int code, const char *fmt, va_list ap) {'), + ('vk_device.c', 'static void lost_wait_exit(void *arg)')] + for file, sig in ends: + text = (rt / file).read_text(encoding='utf-8') + if sig not in text: + print(f'static: {file}: {sig} is missing: FAIL', flush=True) + bad += 1 + continue + start = text.index(sig) + brace = text.index('{', start) + depth, end = 1, brace + 1 + while depth: + depth += (text[end] == '{') - (text[end] == '}') + end += 1 + body = re.sub(r'//[^\n]*', '', text[start:end]) + e, s = body.find('rt_log_ending()'), body.find('rt_log_sync()') + ok = 0 <= e < s + print(f'static: {file} {sig.split("(")[0].split()[-1].lstrip("*")} calls rt_log_ending before rt_log_sync: ' + f'{"ok" if ok else "FAIL"}', flush=True) + bad += not ok + ok = 'plat_exit_hook = log_sync_ending;' in source + print(f'static: main.c plat_exit_hook is log_sync_ending: {"ok" if ok else "FAIL"}', flush=True) + return bad + (not ok) + + def main(): parts = [HARNESS] parts.append(re.search(r'static PlatMutex g_err_lock = PLAT_MUTEX_INIT;\n(.*?\n)\nvoid rt_log_ending', source, re.S) @@ -116,8 +161,8 @@ def main(): if os.name == 'nt' and MSYS_BIN.exists(): env['PATH'] = str(MSYS_BIN) + os.pathsep + env.get('PATH', '') subprocess.check_call([compiler(), '-O1', '-g', '-Wall', '-Wno-unused-function', str(src), '-o', str(exe)], env=env) - bad = 0 - for how in ('ending', 'sync'): + bad = static_checks() + for how in ('ending', 'fatal', 'capture'): bad += subprocess.run([str(exe), how], env=env, timeout=60).returncode != 0 print(f'log_cap_check: {"FAILED" if bad else "ok"}') return 1 if bad else 0