From 76160e81fe9a1ba898e36f9489ffadf3205a2f87 Mon Sep 17 00:00:00 2001 From: capyb2222 Date: Sat, 12 Sep 2026 20:07:05 -0700 Subject: [PATCH] feat(server/game): prettier and faster log --- src/core/logger.cpp | 307 ++++++++++++++++++++++++++++++++++++++------ src/core/logger.h | 17 +++ src/main.cpp | 14 +- tests/test_main.cpp | 44 +++++++ 4 files changed, 338 insertions(+), 44 deletions(-) diff --git a/src/core/logger.cpp b/src/core/logger.cpp index 95e17de..6de1042 100644 --- a/src/core/logger.cpp +++ b/src/core/logger.cpp @@ -1,10 +1,15 @@ #include "core/logger.h" +#include +#include #include +#include #include #include #include +#include #include +#include #ifdef _WIN32 #include @@ -13,10 +18,14 @@ namespace logging { namespace { -std::mutex g_mutex; -Level g_level = Level::Info; -bool g_color = true; -std::ofstream g_file; +// Wide enough for the longest tag in use, "challenge". +constexpr size_t kTagWidth = 10; + +constexpr const char* kReset = "\033[0m"; +constexpr const char* kGray = "\033[90m"; +constexpr const char* kBold = "\033[1m"; + +std::atomic g_level{Level::Info}; const char* levelName(Level l) { switch (l) { @@ -29,21 +38,32 @@ const char* levelName(Level l) { return "?????"; } -const char* levelColor(Level l) { +const char* levelStyle(Level l) { switch (l) { case Level::Trace: return "\033[90m"; case Level::Debug: return "\033[36m"; case Level::Info: return "\033[32m"; - case Level::Warn: return "\033[33m"; - case Level::Error: return "\033[31m"; + case Level::Warn: return "\033[1;33m"; + case Level::Error: return "\033[1;31m"; } return ""; } -std::string timestamp() { - auto now = std::chrono::system_clock::now(); - auto ms = std::chrono::duration_cast(now.time_since_epoch()) % 1000; - std::time_t t = std::chrono::system_clock::to_time_t(now); +// A tag keeps its colour from run to run: it is picked off a hash of the name, from a +// palette that stays clear of the warning and error colours. +const char* tagStyle(std::string_view tag) { + static constexpr const char* kPalette[] = { + "\033[38;5;111m", "\033[38;5;147m", "\033[38;5;180m", "\033[38;5;116m", + "\033[38;5;181m", "\033[38;5;150m", "\033[38;5;139m", "\033[38;5;109m", + }; + uint32_t hash = 2166136261u; + for (unsigned char c : tag) hash = (hash ^ c) * 16777619u; + return kPalette[hash % std::size(kPalette)]; +} + +std::string timeOf(std::chrono::system_clock::time_point when) { + auto ms = std::chrono::duration_cast(when.time_since_epoch()) % 1000; + std::time_t t = std::chrono::system_clock::to_time_t(when); std::tm tm{}; #ifdef _WIN32 localtime_s(&tm, &t); @@ -56,12 +76,229 @@ std::string timestamp() { return buf; } +struct Entry { + std::chrono::system_clock::time_point when; + Level level = Level::Info; + std::string tag; + std::string message; + bool banner = false; + BannerRows rows; +}; + +// The writer and everything it touches. A function-local static, so the thread is joined +// on exit even when main() returns early without calling shutdown(). +class Sink { +public: + ~Sink() { stop(); } + + void start(bool color, const std::string& path) { + std::lock_guard lock(mutex_); + color_ = color; + if (!path.empty() && !file_.is_open()) { + std::error_code ec; + std::filesystem::path parent = std::filesystem::path(path).parent_path(); + if (!parent.empty()) std::filesystem::create_directories(parent, ec); + file_.open(path, std::ios::app); + } + if (!writer_.joinable()) { + stopping_ = false; + writer_ = std::thread([this] { run(); }); + } + } + + void stop() { + { + std::lock_guard lock(mutex_); + if (!writer_.joinable()) return; + stopping_ = true; + } + wake_.notify_one(); + writer_.join(); + std::lock_guard lock(mutex_); + writer_ = std::thread(); + if (file_.is_open()) file_.close(); + } + + void push(Entry entry) { + std::unique_lock lock(mutex_); + if (!writer_.joinable() || stopping_) { + std::string console, file; + render(entry, console, file); + emit(console, file); + return; + } + // The writer drains the whole queue at once, so it only needs waking when it is empty. + bool wasEmpty = queue_.empty(); + queue_.push_back(std::move(entry)); + lock.unlock(); + if (wasEmpty) wake_.notify_one(); + } + +private: + void run() { + std::vector batch; + std::string console, file; + std::unique_lock lock(mutex_); + while (true) { + wake_.wait(lock, [this] { return stopping_ || !queue_.empty(); }); + if (queue_.empty()) return; + batch.swap(queue_); + lock.unlock(); + console.clear(); + file.clear(); + for (const Entry& entry : batch) render(entry, console, file); + batch.clear(); + emit(console, file); + lock.lock(); + } + } + + void render(const Entry& entry, std::string& console, std::string& file) const { + std::string time = timeOf(entry.when); + if (entry.banner) { + console += detail::bannerBox(entry.message, entry.rows, color_); + for (const auto& [label, value] : entry.rows) { + file += detail::fileLine(Level::Info, time, entry.tag, label + " " + value); + } + return; + } + console += detail::consoleLine(entry.level, time, entry.tag, entry.message, color_); + file += detail::fileLine(entry.level, time, entry.tag, entry.message); + } + + // One write and one flush per batch: the console is the slow part. + void emit(const std::string& console, const std::string& file) { + std::lock_guard out(outputMutex_); + if (!console.empty()) { + std::fwrite(console.data(), 1, console.size(), stdout); + std::fflush(stdout); + } + if (file_.is_open() && !file.empty()) { + file_.write(file.data(), static_cast(file.size())); + file_.flush(); + } + } + + std::mutex mutex_; + std::mutex outputMutex_; + std::condition_variable wake_; + std::vector queue_; + std::thread writer_; + bool stopping_ = false; + bool color_ = false; + std::ofstream file_; +}; + +Sink& sink() { + static Sink instance; + return instance; +} + } // namespace +namespace detail { + +std::string consoleLine(Level level, std::string_view time, std::string_view tag, + std::string_view message, bool color) { + std::string out; + out.reserve(time.size() + tag.size() + message.size() + 96); + auto styled = [&](const char* style, std::string_view text) { + if (color) out += style; + out += text; + if (color) out += kReset; + }; + + styled(kGray, time); + out += " "; + styled(levelStyle(level), levelName(level)); + out += " "; + styled(tagStyle(tag), tag); + size_t tagColumn = std::max(kTagWidth, tag.size() + 1); + out.append(tagColumn - tag.size(), ' '); + size_t indent = time.size() + 2 + 5 + 2 + tagColumn; + + bool packet = tag == "recv" || tag == "send"; + size_t start = 0; + while (true) { + size_t end = message.find('\n', start); + std::string_view line = + message.substr(start, end == std::string_view::npos ? std::string_view::npos : end - start); + if (start != 0) { + out += '\n'; + out.append(indent, ' '); + } + if (packet && start == 0 && !line.starts_with(" ")) { + // "DoGachaCsReq (1905) 5 bytes": the name stands out, the numbers step back. + if (tag == "recv") { + styled("\033[32m", color ? "← " : "<- "); + } else { + styled("\033[34m", color ? "→ " : "-> "); + } + size_t split = line.find(" ("); + styled(kBold, line.substr(0, split)); + if (split != std::string_view::npos) styled(kGray, line.substr(split)); + } else if (packet) { + styled(kGray, line); + } else if (level >= Level::Warn) { + styled(levelStyle(level), line); + } else { + out += line; + } + if (end == std::string_view::npos) break; + start = end + 1; + } + out += '\n'; + return out; +} + +std::string fileLine(Level level, std::string_view time, std::string_view tag, + std::string_view message) { + return std::format("{} {} {} {}\n", time, levelName(level), tag, message); +} + +std::string bannerBox(std::string_view title, const BannerRows& rows, bool color) { + size_t labelWidth = 0; + size_t valueWidth = 0; + for (const auto& [label, value] : rows) { + labelWidth = std::max(labelWidth, label.size()); + valueWidth = std::max(valueWidth, value.size()); + } + size_t inner = std::max(labelWidth + 2 + valueWidth, title.size() + 2); + + std::string_view dash = color ? "─" : "-"; + std::string_view bar = color ? "│" : "|"; + auto frame = [color](const std::string& text) { + return color ? std::string(kGray) + text + kReset : text; + }; + auto dashes = [&](size_t n) { + std::string line; + for (size_t i = 0; i < n; ++i) line += dash; + return line; + }; + + std::string out; + out += frame(std::string(color ? "╭" : "+") + std::string(dash) + " "); + out += color ? std::string(kBold) + std::string(title) + kReset : std::string(title); + out += frame(" " + dashes(inner - title.size() - 1) + (color ? "╮" : "+")); + out += '\n'; + for (const auto& [label, value] : rows) { + out += frame(std::string(bar) + " "); + std::string paddedLabel = label + std::string(labelWidth - label.size() + 2, ' '); + out += color ? std::string(kGray) + paddedLabel + kReset : paddedLabel; + out += value; + out.append(inner - labelWidth - 2 - value.size(), ' '); + out += frame(" " + std::string(bar)); + out += '\n'; + } + out += frame(std::string(color ? "╰" : "+") + dashes(inner + 2) + (color ? "╯" : "+")); + out += '\n'; + return out; +} + +} // namespace detail + void init(Level lvl, bool color, const std::string& file) { - std::lock_guard lock(g_mutex); g_level = lvl; - g_color = color; #ifdef _WIN32 if (color) { HANDLE h = GetStdHandle(STD_OUTPUT_HANDLE); @@ -70,38 +307,30 @@ void init(Level lvl, bool color, const std::string& file) { SetConsoleOutputCP(CP_UTF8); } #endif - if (!file.empty()) { - std::error_code ec; - std::filesystem::path parent = std::filesystem::path(file).parent_path(); - if (!parent.empty()) std::filesystem::create_directories(parent, ec); - g_file.open(file, std::ios::app); - } + sink().start(color, file); } -void shutdown() { - std::lock_guard lock(g_mutex); - if (g_file.is_open()) g_file.close(); -} +void shutdown() { sink().stop(); } Level level() { return g_level; } void write(Level lvl, std::string_view tag, std::string_view message) { - std::string ts = timestamp(); - std::lock_guard lock(g_mutex); - if (g_color) { - std::fprintf(stdout, "\033[90m%s\033[0m %s%s\033[0m \033[95m%.*s\033[0m %.*s\n", ts.c_str(), - levelColor(lvl), levelName(lvl), static_cast(tag.size()), tag.data(), - static_cast(message.size()), message.data()); - } else { - std::fprintf(stdout, "%s %s %.*s %.*s\n", ts.c_str(), levelName(lvl), - static_cast(tag.size()), tag.data(), static_cast(message.size()), - message.data()); - } - std::fflush(stdout); - if (g_file.is_open()) { - g_file << ts << ' ' << levelName(lvl) << ' ' << tag << ' ' << message << '\n'; - g_file.flush(); - } + Entry entry; + entry.when = std::chrono::system_clock::now(); + entry.level = lvl; + entry.tag = tag; + entry.message = message; + sink().push(std::move(entry)); +} + +void banner(std::string_view tag, std::string_view title, const BannerRows& rows) { + Entry entry; + entry.when = std::chrono::system_clock::now(); + entry.tag = tag; + entry.message = title; + entry.banner = true; + entry.rows = rows; + sink().push(std::move(entry)); } Level parseLevel(std::string_view name, Level fallback) { diff --git a/src/core/logger.h b/src/core/logger.h index 6a8df3f..5dfcf25 100644 --- a/src/core/logger.h +++ b/src/core/logger.h @@ -3,15 +3,23 @@ #include #include #include +#include +#include namespace logging { enum class Level { Trace = 0, Debug, Info, Warn, Error }; +using BannerRows = std::vector>; + +// After init() a line is only queued; a background thread writes it. Before init() and +// after shutdown() lines are written on the spot. void init(Level level, bool color, const std::string& file); void shutdown(); Level level(); void write(Level level, std::string_view tag, std::string_view message); +// A boxed summary on the console; the file gets one plain line per row under `tag`. +void banner(std::string_view tag, std::string_view title, const BannerRows& rows); inline bool enabled(Level l) { return l >= level(); } @@ -38,4 +46,13 @@ void error(std::string_view tag, std::format_string fmt, Args&&... args Level parseLevel(std::string_view name, Level fallback = Level::Info); +// The formatting, exposed for the tests. +namespace detail { +std::string consoleLine(Level level, std::string_view time, std::string_view tag, + std::string_view message, bool color); +std::string fileLine(Level level, std::string_view time, std::string_view tag, + std::string_view message); +std::string bannerBox(std::string_view title, const BannerRows& rows, bool color); +} // namespace detail + } // namespace logging diff --git a/src/main.cpp b/src/main.cpp index 222106e..13c9915 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -72,12 +72,16 @@ int main(int argc, char** argv) { sdk::registerRoutes(web); sdk::registerAdminRoutes(web, gateway); if (!web.start(config.http.bind, config.http.port)) return 1; - logging::info("capysr", "dispatch listening on {}:{}", config.http.bind, config.http.port); - if (!gateway.start(config.game.bind, config.game.port)) return 1; - logging::info("capysr", "game listening on {}:{} (udp/kcp)", config.game.bind, config.game.port); - logging::info("capysr", "black screen? http://{}:{}/unstick", config.http.publicHost, - config.http.port); + + std::string http = std::format("http://{}:{}", config.http.publicHost, config.http.port); + logging::banner( + "capysr", config.serverName + " is ready", + {{"dispatch", http}, + {"game", std::format("{}:{} udp/kcp", config.game.publicHost, config.game.port)}, + {"unstick", http + "/unstick (black screen?)"}, + {"log", std::format("{} at {}", config.log.file.empty() ? "console only" : config.log.file, + config.log.level)}}); std::signal(SIGINT, onSignal); std::signal(SIGTERM, onSignal); diff --git a/tests/test_main.cpp b/tests/test_main.cpp index 2c0272c..51df34e 100644 --- a/tests/test_main.cpp +++ b/tests/test_main.cpp @@ -1,7 +1,10 @@ // Small assert-based tests; the wire codec is hand written so it gets the most cover. #include #include +#include +#include +#include "core/logger.h" #include "core/util.h" #include "net/cmd_ids.h" #include "net/packet.h" @@ -268,6 +271,46 @@ void testAgainstProtoc() { check(again == std::string(kBytes, size), "re-encoded bytes match protoc"); } +void testLogFormat() { + using logging::Level; + namespace detail = logging::detail; + const char* t = "12:00:00.000"; + + check(detail::consoleLine(Level::Info, t, "game", "hello", false) == + "12:00:00.000 INFO game hello\n", + "console lines keep their columns"); + check(detail::consoleLine(Level::Info, t, "challenge", "x", false) == + "12:00:00.000 INFO challenge x\n", + "the longest tag still leaves a gap"); + check(detail::consoleLine(Level::Debug, t, "recv", "DoGachaCsReq (1905) 5 bytes", false) == + "12:00:00.000 DEBUG recv <- DoGachaCsReq (1905) 5 bytes\n", + "packets get a direction arrow"); + check(detail::consoleLine(Level::Warn, t, "net", "first\nsecond", false) == + "12:00:00.000 WARN net first\n" + std::string(31, ' ') + "second\n", + "a second line lines up under the first"); + check(detail::fileLine(Level::Info, t, "game", "hello") == "12:00:00.000 INFO game hello\n", + "the file keeps its plain format"); + + std::string colored = detail::consoleLine(Level::Debug, t, "send", "X (1) 0 bytes", true); + check(colored.find("\033[") != std::string::npos && colored.find("→") != std::string::npos, + "the console gets colour and arrows"); + + std::string box = detail::bannerBox("CapySR is ready", + {{"dispatch", "http://127.0.0.1:21000"}, {"game", "x"}}, false); + std::vector lines; + for (std::string_view rest = box; !rest.empty();) { + size_t end = rest.find('\n'); + lines.emplace_back(rest.substr(0, end)); + rest.remove_prefix(end + 1); + } + bool even = lines.size() == 4; + for (const std::string& line : lines) even &= line.size() == lines[0].size(); + check(even, "every banner line is the same width"); + check(box.rfind("+- CapySR is ready -", 0) == 0 && + box.find("| dispatch http://127.0.0.1:21000 |") != std::string::npos, + "the banner names its rows"); +} + } // namespace int main() { @@ -280,6 +323,7 @@ int main() { testCmdIds(); testLineupCmdIds(); testIdleTimeout(); + testLogFormat(); testFillPresence(); testLargeMessage(); testAgainstProtoc();