feat(server/game): prettier and faster log

src/core/logger.cpp

@@ -1,10 +1,15 @@
 #include "core/logger.h"
 
+#include <algorithm>
+#include <atomic>
 #include <chrono>
+#include <condition_variable>
 #include <cstdio>
 #include <filesystem>
 #include <fstream>
+#include <iterator>
 #include <mutex>
+#include <thread>
 
 #ifdef _WIN32
 #include <windows.h>
@@ -13,10 +18,14 @@
 namespace logging {
 namespace {
 
-std::mutex g_mutex;
+// Wide enough for the longest tag in use, "challenge".
-Level g_level = Level::Info;
+constexpr size_t kTagWidth = 10;
-bool g_color = true;
+
-std::ofstream g_file;
+constexpr const char* kReset = "\033[0m";
+constexpr const char* kGray = "\033[90m";
+constexpr const char* kBold = "\033[1m";
+
+std::atomic<Level> 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::Warn: return "\033[1;33m";
-        case Level::Error: return "\033[31m";
+        case Level::Error: return "\033[1;31m";
     }
     return "";
 }
 
-std::string timestamp() {
+// A tag keeps its colour from run to run: it is picked off a hash of the name, from a
-    auto now = std::chrono::system_clock::now();
+// palette that stays clear of the warning and error colours.
-    auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
+const char* tagStyle(std::string_view tag) {
-    std::time_t t = std::chrono::system_clock::to_time_t(now);
+    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<std::chrono::milliseconds>(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<Entry> 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<std::streamsize>(file.size()));
+            file_.flush();
+        }
+    }
+
+    std::mutex mutex_;
+    std::mutex outputMutex_;
+    std::condition_variable wake_;
+    std::vector<Entry> 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()) {
+    sink().start(color, file);
-        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);
-    }
 }
 
-void shutdown() {
+void shutdown() { sink().stop(); }
-    std::lock_guard lock(g_mutex);
-    if (g_file.is_open()) g_file.close();
-}
 
 Level level() { return g_level; }
 
 void write(Level lvl, std::string_view tag, std::string_view message) {
-    std::string ts = timestamp();
+    Entry entry;
-    std::lock_guard lock(g_mutex);
+    entry.when = std::chrono::system_clock::now();
-    if (g_color) {
+    entry.level = lvl;
-        std::fprintf(stdout, "\033[90m%s\033[0m %s%s\033[0m \033[95m%.*s\033[0m %.*s\n", ts.c_str(),
+    entry.tag = tag;
-                     levelColor(lvl), levelName(lvl), static_cast<int>(tag.size()), tag.data(),
+    entry.message = message;
-                     static_cast<int>(message.size()), message.data());
+    sink().push(std::move(entry));
-    } else {
+}
-        std::fprintf(stdout, "%s %s %.*s %.*s\n", ts.c_str(), levelName(lvl),
+
-                     static_cast<int>(tag.size()), tag.data(), static_cast<int>(message.size()),
+void banner(std::string_view tag, std::string_view title, const BannerRows& rows) {
-                     message.data());
+    Entry entry;
-    }
+    entry.when = std::chrono::system_clock::now();
-    std::fflush(stdout);
+    entry.tag = tag;
-    if (g_file.is_open()) {
+    entry.message = title;
-        g_file << ts << ' ' << levelName(lvl) << ' ' << tag << ' ' << message << '\n';
+    entry.banner = true;
-        g_file.flush();
+    entry.rows = rows;
-    }
+    sink().push(std::move(entry));
 }
 
 Level parseLevel(std::string_view name, Level fallback) {

src/core/logger.h

@@ -3,15 +3,23 @@
 #include <format>
 #include <string>
 #include <string_view>
+#include <utility>
+#include <vector>
 
 namespace logging {
 
 enum class Level { Trace = 0, Debug, Info, Warn, Error };
 
+using BannerRows = std::vector<std::pair<std::string, std::string>>;
+
+// 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<Args...> 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

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,
+    std::string http = std::format("http://{}:{}", config.http.publicHost, config.http.port);
-                  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);

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 <cstdio>
 #include <string>
+#include <string_view>
+#include <vector>
 
+#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<std::string> 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();