// SpeedBreaker runtime. GPL-3.0-or-later (see COPYING). See report.h. // // The session log. A tee through a pipe rather than a hook on the stderr // FILE: the drivers, SDL, the C library's own messages (an assert, a heap // check) and a child process write to fd 2 directly. One thread copies the // pipe to the original stderr, to the file and to a 64 KB ring in memory; // each chunk reaches the kernel as soon as it is written, so nothing waits // in a user-space buffer for a crash to lose. In the file and the ring each // line starts with the seconds since launch ("[ 612.3] "), so a tester's // "it froze about ten minutes in" finds its place; the terminal gets the // lines as they were written. #include #include "report.h" #include "internal.h" #include #include #include #include #include #include #include #include namespace report { namespace { constexpr size_t kRingSize = 64 * 1024; constexpr uint64_t kDefaultCapBytes = 16ull << 20; constexpr size_t kKeepSessions = 5; char s_ring[kRingSize]; std::atomic s_ringTotal{ 0 }; // bytes ever appended; the ring holds the last kRingSize int s_pipeRead = -1; std::atomic s_terminal{ -1 }; // the original stderr (-1 once it's gone) std::atomic s_file{ -1 }; uint64_t s_fileBytes = 0; // writer thread only uint64_t s_capBytes = kDefaultCapBytes; std::atomic s_busy{ false }; // the writer holds a chunk it hasn't finished with std::atomic s_chunks{ 0 }; // chunks finished std::atomic s_writerStarted{ false }; pthread_t s_writer{}; char s_sessionName[64] = ""; std::filesystem::path s_logPath; std::chrono::steady_clock::time_point s_start = std::chrono::steady_clock::now(); void FileWrite(const char* data, size_t size) { int fd = s_file.load(std::memory_order_relaxed); if (fd < 0) return; if (s_fileBytes + size <= s_capBytes) { detail::WriteAll(fd, data, size); s_fileBytes += size; return; } // Whole lines up to the cap, then one notice. A runaway log can't // fill the disk; the ring (and so any crash or hang report) still // has the latest lines. size_t fit = s_capBytes > s_fileBytes ? size_t(s_capBytes - s_fileBytes) : 0; while (fit > 0 && data[fit - 1] != '\n') fit--; detail::WriteAll(fd, data, fit); static const char notice[] = "\n[log] this session's log reached its size cap (NFSMW_LOG_MAX_KB): later output is " "not saved here; crash and hang reports still get the last lines\n"; detail::WriteAll(fd, notice, sizeof(notice) - 1); s_file.store(-1, std::memory_order_relaxed); // stays open for the crash handler's direct writes s_fileBytes = s_capBytes; } int s_cappedFd = -1; // the file after the cap: only the crash handler writes to it void RingAppend(const char* data, size_t size) { uint64_t total = s_ringTotal.load(std::memory_order_relaxed); if (size > kRingSize) { total += size - kRingSize; data += size - kRingSize; size = kRingSize; } size_t pos = size_t(total % kRingSize); size_t first = std::min(size, kRingSize - pos); memcpy(s_ring + pos, data, first); memcpy(s_ring, data + first, size - first); s_ringTotal.store(total + size, std::memory_order_release); } void Writer() { SetHostThreadName("nfsmw-log"); // A terminal that went away must not kill the game: with SIGPIPE // blocked here, the write fails with EPIPE instead. sigset_t set; sigemptyset(&set); sigaddset(&set, SIGPIPE); pthread_sigmask(SIG_BLOCK, &set, nullptr); static char buffer[16384]; static char stamped[sizeof(buffer) * 13]; // room for a prefix on every byte bool lineStart = true; while (true) { ssize_t n = read(s_pipeRead, buffer, sizeof(buffer)); if (n < 0 && errno == EINTR) continue; if (n <= 0) return; s_busy.store(true, std::memory_order_release); char prefix[32]; int prefixSize = snprintf(prefix, sizeof(prefix), "[%7.1f] ", SessionSeconds()); prefixSize = std::clamp(prefixSize, 0, 12); size_t size = 0; for (ssize_t i = 0; i < n; i++) { if (lineStart) { memcpy(stamped + size, prefix, size_t(prefixSize)); size += size_t(prefixSize); } stamped[size++] = buffer[i]; lineStart = buffer[i] == '\n'; } if (int fd = s_terminal.load(std::memory_order_relaxed); fd >= 0) { for (size_t done = 0; done < size_t(n);) { ssize_t w = write(fd, buffer + done, size_t(n) - done); if (w < 0 && errno == EINTR) continue; if (w <= 0) { s_terminal.store(-1, std::memory_order_relaxed); // closed: the file carries on alone break; } done += size_t(w); } } FileWrite(stamped, size); RingAppend(stamped, size); s_chunks.fetch_add(1, std::memory_order_release); s_busy.store(false, std::memory_order_release); } } // [first, last) of the ring: the last `maxLines` whole lines. void TailRange(size_t maxLines, uint64_t& first, uint64_t& last) { last = s_ringTotal.load(std::memory_order_acquire); uint64_t oldest = last > kRingSize ? last - kRingSize : 0; // Leave a margin the writer may be overwriting as we read. if (last > kRingSize) oldest += 4096; uint64_t i = last; size_t lines = 0; while (i > oldest) { if (s_ring[(i - 1) % kRingSize] == '\n' && i != last && ++lines == maxLines) break; i--; } if (i == oldest && last > kRingSize) { // The oldest line may be cut: start at the next whole one. while (i < last && s_ring[i % kRingSize] != '\n') i++; if (i < last) i++; } first = i; } } namespace detail { SafeBuf& SafeBuf::Str(const char* s) { while (s && *s && size < capacity) data[size++] = *s++; return *this; } SafeBuf& SafeBuf::Str(const char* s, size_t n) { for (size_t i = 0; i < n && size < capacity; i++) data[size++] = s[i]; return *this; } SafeBuf& SafeBuf::Char(char c) { if (size < capacity) data[size++] = c; return *this; } SafeBuf& SafeBuf::Dec(int64_t v) { char digits[24]; int n = 0; uint64_t u = v < 0 ? uint64_t(0) - uint64_t(v) : uint64_t(v); do digits[n++] = char('0' + u % 10); while ((u /= 10) != 0); if (v < 0) Char('-'); while (n > 0) Char(digits[--n]); return *this; } SafeBuf& SafeBuf::Hex(uint64_t v, int minDigits, bool upper) { char digits[16]; int n = 0; do { digits[n++] = (upper ? "0123456789ABCDEF" : "0123456789abcdef")[v & 15]; v >>= 4; } while (v != 0); while (n < minDigits && n < 16) digits[n++] = '0'; while (n > 0) Char(digits[--n]); return *this; } void WriteAll(int fd, const void* data, size_t size) { if (fd < 0) return; const char* p = static_cast(data); while (size > 0) { ssize_t n = write(fd, p, size); if (n < 0 && errno == EINTR) continue; if (n <= 0) return; p += n; size -= size_t(n); } } int TerminalFd() { int fd = s_terminal.load(std::memory_order_relaxed); return s_pipeRead >= 0 ? fd : 2; // no tee: stderr is still the terminal } bool LogCapped() { return s_file.load(std::memory_order_relaxed) < 0 && s_cappedFd >= 0; } int LogFileFd() { int fd = s_file.load(std::memory_order_relaxed); return fd >= 0 ? fd : s_cappedFd; } void WriteDirect(const char* data, size_t size) { WriteAll(TerminalFd(), data, size); WriteAll(LogFileFd(), data, size); } void WriteRecentOutput(int fd, size_t maxLines) { uint64_t first, last; TailRange(maxLines, first, last); while (first < last) { size_t pos = size_t(first % kRingSize); size_t n = size_t(std::min(last - first, kRingSize - pos)); WriteAll(fd, s_ring + pos, n); first += n; } } void KeepNewest(const std::string& dir, const char* prefix, const char* suffix, size_t keep) { std::vector files; std::error_code ec; for (std::filesystem::directory_iterator it(dir, ec), end; !ec && it != end; it.increment(ec)) { std::string name = it->path().filename().string(); if (name.empty() || name[0] == '.' || !name.starts_with(prefix) || !name.ends_with(suffix)) continue; if (it->is_regular_file(ec)) files.push_back(it->path()); } if (files.size() <= keep) return; std::sort(files.begin(), files.end()); for (size_t i = 0; i + keep < files.size(); i++) std::filesystem::remove(files[i], ec); } std::string TimeStamp() { time_t now = time(nullptr); struct tm local{}; localtime_r(&now, &local); char text[32]; strftime(text, sizeof(text), "%Y-%m-%d_%H-%M-%S", &local); return text; } } void StartSessionLog() { s_start = std::chrono::steady_clock::now(); std::string stamp = detail::TimeStamp(); snprintf(s_sessionName, sizeof(s_sessionName), "%s", stamp.c_str()); if (const char* v = std::getenv("NFSMW_SESSION_LOG"); v && v[0] == '0') { fprintf(stderr, "[build] SpeedBreaker %s\n", BuildString()); fprintf(stderr, "[log] no session log (NFSMW_SESSION_LOG=0)\n"); return; } if (const char* v = std::getenv("NFSMW_LOG_MAX_KB")) if (long kb = std::atol(v); kb > 0) s_capBytes = uint64_t(kb) << 10; // The file: .log, or -2.log if another instance started // in the same second. The newest kKeepSessions stay (with this one). std::filesystem::path dir = LogDirectory(); std::error_code ec; std::filesystem::create_directories(dir, ec); detail::KeepNewest(dir.string(), "", ".log", kKeepSessions - 1); int file = -1; for (int attempt = 1; attempt < 10 && file < 0; attempt++) { std::string name = attempt == 1 ? stamp : std::format("{}-{}", stamp, attempt); std::filesystem::path path = dir / (name + ".log"); file = open(path.c_str(), O_WRONLY | O_CREAT | O_EXCL | O_APPEND | O_CLOEXEC, 0644); if (file >= 0) { snprintf(s_sessionName, sizeof(s_sessionName), "%s", name.c_str()); s_logPath = path; } else if (errno != EEXIST) break; } if (file < 0) fprintf(stderr, "[log] can't create a session log in %s: %s\n", dir.c_str(), strerror(errno)); else if (file <= 2) { // Launched with stderr (or stdin, stdout) closed, open() hands // out its number: as fd 2 the file would be replaced by the pipe // below, and the copying thread would feed the pipe to itself // forever (one core busy, the log growing without its cap). int moved = fcntl(file, F_DUPFD_CLOEXEC, 3); close(file); file = moved; } // fd 2 becomes the pipe; the writer copies it on (StartLogWriter). int fds[2]; if (pipe(fds) != 0) { fprintf(stderr, "[build] SpeedBreaker %s\n", BuildString()); fprintf(stderr, "[log] pipe: %s (no session log)\n", strerror(errno)); if (file >= 0) close(file); return; } // With stdin, stdout or stderr closed, pipe() hands out their // numbers: move both ends above them before fd 2 is replaced. for (int& fd : fds) if (fd <= 2) { int moved = fcntl(fd, F_DUPFD_CLOEXEC, 3); close(fd); fd = moved; } if (fds[0] < 0 || fds[1] < 0) { fprintf(stderr, "[build] SpeedBreaker %s\n", BuildString()); fprintf(stderr, "[log] pipe: out of descriptors (no session log)\n"); if (file >= 0) close(file); return; } fcntl(fds[0], F_SETFD, FD_CLOEXEC); #ifdef F_SETPIPE_SZ // Room for a burst (and for startup, before the writer runs). fcntl(fds[1], F_SETPIPE_SZ, 1 << 20); #endif fflush(stderr); int terminal = fcntl(2, F_DUPFD_CLOEXEC, 3); if (dup2(fds[1], 2) < 0) { fprintf(stderr, "[build] SpeedBreaker %s\n", BuildString()); fprintf(stderr, "[log] dup2: %s (no session log)\n", strerror(errno)); close(fds[0]); close(fds[1]); if (terminal >= 0) close(terminal); if (file >= 0) close(file); return; } close(fds[1]); // A write that failed before (stderr closed at launch: the // NFSMW_INPUT_SCRIPT line, any message before this) leaves the // stream's error flag set, and macOS's fprintf then writes nothing, // not even to the pipe (fputs still does): the log kept a handful // of lines out of hundreds. clearerr(stderr); s_pipeRead = fds[0]; s_terminal.store(terminal, std::memory_order_relaxed); s_file.store(file, std::memory_order_relaxed); s_cappedFd = file; // The first lines of the file. fprintf(stderr, "[build] SpeedBreaker %s\n", BuildString()); if (file >= 0) fprintf(stderr, "[log] session %s (pid %d): %s\n", s_sessionName, int(getpid()), s_logPath.c_str()); } void StartLogWriter() { if (s_pipeRead < 0 || s_writerStarted.load()) return; std::thread writer(Writer); s_writer = writer.native_handle(); writer.detach(); s_writerStarted.store(true, std::memory_order_release); // A return from main() or an exit() (a usage message, "the game // isn't installed") ends this thread with the process too: let the // pipe drain first, as every std::_Exit does, or the message never // reaches the terminal or the file. std::atexit(FlushLog); } const char* SessionName() { return s_sessionName; } std::filesystem::path LogDirectory() { return GetUserPath() / "logs"; } std::filesystem::path SessionLogPath() { return s_logPath; } double SessionSeconds() { return std::chrono::duration(std::chrono::steady_clock::now() - s_start).count(); } std::string RecentOutput(size_t maxLines) { uint64_t first, last; TailRange(maxLines, first, last); std::string text; text.reserve(size_t(last - first)); for (uint64_t i = first; i < last; i++) text.push_back(s_ring[i % kRingSize]); return text; } void FlushLog() { if (s_pipeRead < 0 || !s_writerStarted.load(std::memory_order_acquire) || pthread_equal(pthread_self(), s_writer)) return; // Empty pipe and an idle writer, twice a millisecond apart with no // chunk finished in between (it may have just taken the last one). int quiet = 0; uint64_t chunks = s_chunks.load(std::memory_order_acquire); for (int i = 0; i < 250 && quiet < 2; i++) { int pending = 0; ioctl(s_pipeRead, FIONREAD, &pending); uint64_t now = s_chunks.load(std::memory_order_acquire); quiet = (pending == 0 && !s_busy.load(std::memory_order_acquire) && now == chunks) ? quiet + 1 : 0; chunks = now; struct timespec ms{ 0, 1000000 }; nanosleep(&ms, nullptr); } } }