feat: add observability — log module, --verbose, file logging (#68)

* feat: add observability — log module, --verbose, file logging

Three-layer observability system:

1. mcpp::log module (src/log.cppm):
   - File-based logging to ~/.mcpp/log/mcpp.log
   - Log rotation (10MB, 3 files)
   - Levels: off/error/warn/info/debug
   - Configured via MCPP_LOG_LEVEL env var or config.toml [log]

2. --verbose global flag:
   - Shows detailed progress on stderr (dim gray)
   - Auto-enables info-level file logging
   - Covers: toolchain install, package fetch, post-install fixup

3. Key path instrumentation:
   - Toolchain install flow (target, deps, fixup steps)
   - Package fetcher (resolve path, copy workaround, xlings calls)
   - xlings event forwarding (LogEvent, ErrorEvent)
   - Toolchain probing (compiler binary, sysroot, payload paths)

* fix: use localtime_s on Windows for log timestamp

Author: Sunrisepeak

src/cli.cppm

@@ -41,6 +41,7 @@ import mcpp.pm.mangle;     // Level 1 multi-version fallback (cross-major coexis
 import mcpp.pm.compat;     // 0.0.6: namespace field + dotted-name compat shims
 import mcpp.pm.dep_spec;
 import mcpp.ui;
+import mcpp.log;
 import mcpp.bmi_cache;
 import mcpp.dyndep;
 import mcpp.version_req;   // SemVer constraint resolution
@@ -559,6 +560,22 @@ struct CliInstallProgress : mcpp::fetcher::EventHandler {
         }
     }
 
+    void on_log(const mcpp::fetcher::LogEvent& e) override {
+        if (e.level == "error")
+            mcpp::log::error("xlings", e.message);
+        else if (e.level == "warn")
+            mcpp::log::warn("xlings", e.message);
+        else
+            mcpp::log::info("xlings", e.message);
+        mcpp::log::verbose("xlings", std::format("[{}] {}", e.level, e.message));
+    }
+
+    void on_error(const mcpp::fetcher::ErrorEvent& e) override {
+        mcpp::log::error("xlings", std::format("{}: {}", e.code, e.message));
+        if (!e.hint.empty())
+            mcpp::log::info("xlings", std::format("hint: {}", e.hint));
+    }
+
     ~CliInstallProgress() override { if (bar_) bar_->finish(); }
 };
 
@@ -2637,7 +2654,7 @@ std::optional<int> try_fast_build(const std::filesystem::path& projectRoot,
 }
 
 int cmd_build(const mcpplibs::cmdline::ParsedArgs& parsed) {
-    bool verbose  = parsed.is_flag_set("verbose");
+    bool verbose  = parsed.is_flag_set("verbose") || mcpp::log::is_verbose();
     bool print_fp = parsed.is_flag_set("print-fingerprint");
     bool no_cache = parsed.is_flag_set("no-cache");
 
@@ -3723,6 +3740,11 @@ int cmd_toolchain(const mcpplibs::cmdline::ParsedArgs& parsed) {
 
         mcpp::ui::info("Installing",
             std::format("{} {} via mcpp's xlings", spec->compiler, spec->version));
+        mcpp::log::verbose("toolchain", std::format(
+            "install: target='{}' xlingsHome='{}'", pkg.target(), cfg->xlingsHome().string()));
+        mcpp::log::debug("toolchain", std::format(
+            "  ximName='{}' needsGccFixup={} xlingsBinary='{}'",
+            pkg.ximName, pkg.needsGccPostInstallFixup, cfg->xlingsBinary.string()));
         mcpp::fetcher::Fetcher fetcher(*cfg);
         CliInstallProgress progress;
 
@@ -3731,13 +3753,17 @@ int cmd_toolchain(const mcpplibs::cmdline::ParsedArgs& parsed) {
         // musl-gcc is self-contained and doesn't need these.
         if (!spec->isMusl) {
             for (auto dep : {"xim:glibc", "xim:linux-headers"}) {
+                mcpp::log::verbose("toolchain", std::format("installing dep: {}", dep));
                 auto depPayload = fetcher.resolve_xpkg_path(dep, /*autoInstall=*/true, &progress);
-                // Best-effort: linux-headers may not be in the index.
-                // glibc is usually a dependency of gcc/llvm and already installed.
+                mcpp::log::debug("toolchain", std::format("dep {} result: {}",
+                    dep, depPayload ? "ok" : depPayload.error().message));
             }
         }
 
+        mcpp::log::verbose("toolchain", std::format("installing main: {}", pkg.target()));
         auto payload = fetcher.resolve_xpkg_path(pkg.target(), /*autoInstall=*/true, &progress);
+        mcpp::log::verbose("toolchain", std::format("main install result: {}",
+            payload ? ("ok → " + payload->root.string()) : payload.error().message));
         if (!payload) {
             mcpp::ui::error(std::format("install failed: {}", payload.error().message));
             return 1;
@@ -3786,6 +3812,8 @@ int cmd_toolchain(const mcpplibs::cmdline::ParsedArgs& parsed) {
 
                 // (1) patchelf walk: rewrite PT_INTERP + RUNPATH for binutils
                 //     and gcc xpkgs so they're self-contained in sandbox.
+                mcpp::log::verbose("toolchain", std::format(
+                    "gcc fixup: patchelf_walk rpath='{}'", rpath));
                 auto binutilsRoot = mcpp::xlings::paths::xim_tool_root(xlEnv, "binutils");
                 if (std::filesystem::exists(binutilsRoot)) {
                     for (auto& v : std::filesystem::directory_iterator(binutilsRoot))
@@ -3794,6 +3822,7 @@ int cmd_toolchain(const mcpplibs::cmdline::ParsedArgs& parsed) {
                 patchelf_walk(payload->root, loader, rpath, patchelfBin);
 
                 // (2) specs fixup.
+                mcpp::log::verbose("toolchain", "gcc fixup: fixup_gcc_specs");
                 fixup_gcc_specs(payload->root, glibcLibDir, gccLibDir);
             } else {
                 mcpp::ui::warning(
@@ -3841,9 +3870,12 @@ int cmd_toolchain(const mcpplibs::cmdline::ParsedArgs& parsed) {
                 std::string rpath = llvmTargetLib.string()
                     + ":" + llvmLib.string()
                     + ":" + glibcLibDir.string();
+                mcpp::log::verbose("toolchain", std::format(
+                    "llvm fixup: patchelf_walk lib/ rpath='{}'", rpath));
                 patchelf_walk(llvmLib, loader, rpath, patchelfBin);
             }
 
+            mcpp::log::verbose("toolchain", "llvm fixup: fixup_clang_cfg");
             fixup_clang_cfg(payload->root, glibcLibDir);
         }
 
@@ -4353,6 +4385,7 @@ int run(int argc, char** argv) {
         std::string_view a = argv[i];
         if      (a == "--quiet" || a == "-q") mcpp::ui::set_quiet(true);
         else if (a == "--no-color")           mcpp::ui::disable_color();
+        else if (a == "--verbose" || a == "-v") mcpp::log::set_verbose(true);
     }
 
     // ─── top-level --help / -h / --version intercept ────────────────────
@@ -4441,6 +4474,8 @@ int run(int argc, char** argv) {
         .description("modern C++ build tool")
         .option(cl::Option("quiet").short_name('q')
             .help("Suppress status output").global())
+        .option(cl::Option("verbose").short_name('v')
+            .help("Show detailed progress on stderr").global())
         .option(cl::Option("no-color")
             .help("Disable colored output").global())
 
@@ -4451,8 +4486,6 @@ int run(int argc, char** argv) {
             .action(wrap_rc(cmd_new)))
         .subcommand(cl::App("build")
             .description("Build the current package")
-            .option(cl::Option("verbose").short_name('v')
-                .help("Verbose compiler output"))
             .option(cl::Option("print-fingerprint")
                 .help("Show toolchain fingerprint and 10 inputs"))
             .option(cl::Option("no-cache")

src/config.cppm

@@ -23,6 +23,7 @@ import mcpp.libs.toml;
 import mcpp.pm.index_spec;
 import mcpp.xlings;
 import mcpp.platform;
+import mcpp.log;
 
 export namespace mcpp::config {
 
@@ -460,6 +461,13 @@ std::expected<GlobalConfig, ConfigError> load_or_init(
             std::format("cannot create '{}': {}", d.string(), ec.message())});
     }
 
+    // 2b. Initialize logger (early init with defaults; re-init after config load)
+    {
+        mcpp::log::Config logCfg;
+        logCfg.logDir = cfg.logDir;
+        mcpp::log::init(logCfg);
+    }
+
     // 3. Seed config.toml if missing
     bool fresh_config = !std::filesystem::exists(cfg.configFile);
     if (fresh_config) write_default_config_toml(cfg.configFile);
@@ -481,6 +489,22 @@ std::expected<GlobalConfig, ConfigError> load_or_init(
     cfg.defaultBackend = doc->get_string("build.default_backend").value_or("ninja");
     cfg.defaultToolchain = doc->get_string("toolchain.default").value_or("");
 
+    // [log] section — re-initialize logger with config values
+    {
+        mcpp::log::Config logCfg;
+        logCfg.logDir = cfg.logDir;
+        auto levelStr = doc->get_string("log.level").value_or("off");
+        if      (levelStr == "debug") logCfg.level = mcpp::log::Level::debug;
+        else if (levelStr == "info")  logCfg.level = mcpp::log::Level::info;
+        else if (levelStr == "warn")  logCfg.level = mcpp::log::Level::warn;
+        else if (levelStr == "error") logCfg.level = mcpp::log::Level::error;
+        logCfg.maxFileSize = static_cast<std::size_t>(
+            doc->get_int("log.max_file_size").value_or(10 * 1024 * 1024));
+        logCfg.maxFiles = static_cast<int>(
+            doc->get_int("log.max_files").value_or(3));
+        mcpp::log::init(logCfg);
+    }
+
     // [index.repos.NAME] tables
     if (auto* repos = doc->get_table("index.repos")) {
         for (auto& [name, val] : *repos) {

src/log.cppm

@@ -0,0 +1,215 @@
+// mcpp.log — file-based debug logger with verbose terminal output.
+//
+// Usage:
+//   mcpp::log::init(cfg);              // call once at startup
+//   mcpp::log::debug("tag", "msg");    // writes to ~/.mcpp/log/mcpp.log
+//   mcpp::log::verbose("tag", "msg");  // file + stderr (when --verbose)
+//
+// Configuration (priority order):
+//   1. MCPP_LOG_LEVEL env var: "debug" | "info" | "warn" | "error" | "off"
+//   2. config.toml [log].level
+//   3. Default: "off"
+//
+// Log file: <logDir>/mcpp.log (rotated at max_file_size, keeps max_files)
+
+module;
+#include <ctime>
+#include <cstdio>
+
+export module mcpp.log;
+
+import std;
+
+export namespace mcpp::log {
+
+enum class Level { off, error, warn, info, debug };
+
+struct Config {
+    Level                   level        = Level::off;
+    std::size_t             maxFileSize  = 10 * 1024 * 1024;  // 10MB
+    int                     maxFiles     = 3;
+    std::filesystem::path   logDir;
+};
+
+void init(const Config& cfg);
+
+void debug(std::string_view tag, std::string_view message);
+void info (std::string_view tag, std::string_view message);
+void warn (std::string_view tag, std::string_view message);
+void error(std::string_view tag, std::string_view message);
+
+// verbose: writes to file (level >= info) AND stderr (when --verbose).
+void set_verbose(bool v);
+bool is_verbose();
+void verbose(std::string_view tag, std::string_view message);
+
+// Check if a level is enabled (avoid constructing expensive messages).
+bool is_enabled(Level l);
+
+} // namespace mcpp::log
+
+// ─── Implementation ─────────────────────────────────────────────────
+
+namespace mcpp::log {
+
+namespace {
+
+Level                   g_level    = Level::off;
+bool                    g_verbose  = false;
+std::filesystem::path   g_logFile;
+std::size_t             g_maxFileSize = 10 * 1024 * 1024;
+int                     g_maxFiles    = 3;
+std::mutex              g_mutex;
+
+Level parse_level(const char* s) {
+    if (!s || !*s) return Level::off;
+    std::string v(s);
+    for (auto& c : v) c = static_cast<char>(std::tolower(static_cast<unsigned char>(c)));
+    if (v == "debug") return Level::debug;
+    if (v == "info")  return Level::info;
+    if (v == "warn")  return Level::warn;
+    if (v == "error") return Level::error;
+    return Level::off;
+}
+
+std::string timestamp() {
+    auto now = std::chrono::system_clock::now();
+    auto tt  = std::chrono::system_clock::to_time_t(now);
+    auto ms  = std::chrono::duration_cast<std::chrono::milliseconds>(
+                   now.time_since_epoch()) % 1000;
+    std::tm tm{};
+#if defined(_WIN32)
+    localtime_s(&tm, &tt);
+#else
+    localtime_r(&tt, &tm);
+#endif
+    char buf[32];
+    std::snprintf(buf, sizeof(buf), "%04d-%02d-%02d %02d:%02d:%02d.%03d",
+        tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+        tm.tm_hour, tm.tm_min, tm.tm_sec, static_cast<int>(ms.count()));
+    return buf;
+}
+
+const char* level_str(Level l) {
+    switch (l) {
+        case Level::debug: return "DEBUG";
+        case Level::info:  return "INFO ";
+        case Level::warn:  return "WARN ";
+        case Level::error: return "ERROR";
+        default:           return "     ";
+    }
+}
+
+void rotate() {
+    if (g_logFile.empty() || g_maxFiles <= 0) return;
+    std::error_code ec;
+    auto size = std::filesystem::file_size(g_logFile, ec);
+    if (ec || size < g_maxFileSize) return;
+
+    // mcpp.log.2 → delete, mcpp.log.1 → mcpp.log.2, mcpp.log → mcpp.log.1
+    for (int i = g_maxFiles - 1; i >= 1; --i) {
+        auto src = g_logFile;
+        src += "." + std::to_string(i);
+        auto dst = g_logFile;
+        dst += "." + std::to_string(i + 1);
+        if (i == g_maxFiles - 1) {
+            std::filesystem::remove(src, ec);
+        } else {
+            std::filesystem::rename(src, dst, ec);
+        }
+    }
+    auto first = g_logFile;
+    first += ".1";
+    std::filesystem::rename(g_logFile, first, ec);
+}
+
+void write_log(Level level, std::string_view tag, std::string_view message) {
+    if (level > g_level || g_level == Level::off) return;
+    if (g_logFile.empty()) return;
+
+    std::lock_guard lock(g_mutex);
+    rotate();
+    std::ofstream ofs(g_logFile, std::ios::app);
+    if (!ofs) return;
+    ofs << timestamp() << " [" << level_str(level) << "] "
+        << tag << ": " << message << '\n';
+}
+
+void write_stderr(std::string_view tag, std::string_view message) {
+    // Dim gray for verbose output so it doesn't compete with ui::status
+    std::fprintf(stderr, "\033[2m[VERBOSE] %.*s: %.*s\033[0m\n",
+        static_cast<int>(tag.size()), tag.data(),
+        static_cast<int>(message.size()), message.data());
+}
+
+} // namespace
+
+void init(const Config& cfg) {
+    // Priority: env var > --verbose > config > default
+    if (auto* e = std::getenv("MCPP_LOG_LEVEL"); e && *e) {
+        g_level = parse_level(e);
+    } else if (g_verbose && cfg.level == Level::off) {
+        g_level = Level::info;  // --verbose auto-enables info
+    } else {
+        g_level = cfg.level;
+    }
+
+    g_maxFileSize = cfg.maxFileSize;
+    g_maxFiles    = cfg.maxFiles;
+
+    if (g_level == Level::off && !g_verbose) return;
+
+    std::error_code ec;
+    std::filesystem::create_directories(cfg.logDir, ec);
+    g_logFile = cfg.logDir / "mcpp.log";
+
+    // Only write session marker on first init (avoid duplicate from re-init)
+    static bool session_started = false;
+    if (!session_started) {
+        session_started = true;
+        write_log(Level::info, "log",
+            std::format("=== session start (level={} verbose={}) ===",
+                level_str(g_level), g_verbose));
+    }
+}
+
+void set_verbose(bool v) {
+    g_verbose = v;
+    // If verbose enabled but file logging off, auto-enable info level
+    if (v && g_level == Level::off) {
+        g_level = Level::info;
+        if (!g_logFile.empty()) return;
+        // Deferred: logDir not set yet, init() will handle it
+    }
+}
+
+bool is_verbose() { return g_verbose; }
+
+bool is_enabled(Level l) {
+    return l <= g_level && g_level != Level::off;
+}
+
+void debug(std::string_view tag, std::string_view message) {
+    write_log(Level::debug, tag, message);
+}
+
+void info(std::string_view tag, std::string_view message) {
+    write_log(Level::info, tag, message);
+}
+
+void warn(std::string_view tag, std::string_view message) {
+    write_log(Level::warn, tag, message);
+}
+
+void error(std::string_view tag, std::string_view message) {
+    write_log(Level::error, tag, message);
+}
+
+void verbose(std::string_view tag, std::string_view message) {
+    write_log(Level::info, tag, message);
+    if (g_verbose) {
+        write_stderr(tag, message);
+    }
+}
+
+} // namespace mcpp::log