Merge pull request #13 from DeterminateSystems/logger-improvements

Logger improvements

doc/manual/source/SUMMARY.md.in

@@ -129,7 +129,7 @@
 - [Determinate Nix Release Notes](release-notes-determinate/index.md)
   - [Changes between Nix and Determinate Nix](release-notes-determinate/changes.md)
   - [Release 3.0.0 (2025-03-04)](release-notes-determinate/rl-3.0.0.md)
-  - [Release 3.1.0 (2025-??-??)](release-notes-determinate/rl-3.1.0.md)
+  - [Release 3.1.0 (2025-03-27)](release-notes-determinate/rl-3.1.0.md)
 - [Nix Release Notes](release-notes/index.md)
 {{#include ./SUMMARY-rl-next.md}}
   - [Release 2.27 (2025-03-03)](release-notes/rl-2.27.md)

doc/manual/source/release-notes-determinate/changes.md

@@ -5,3 +5,5 @@ This section lists the differences between upstream Nix 2.24 and Determinate Nix
 * In Determinate Nix, flakes are stable. You no longer need to enable the `flakes` experimental feature.
 
 * In Determinate Nix, the new Nix CLI (i.e. the `nix` command) is stable. You no longer need to enable the `nix-command` experimental feature.
+
+* Determinate Nix has a setting [`json-log-path`](@docroot@/command-ref/conf-file.md#conf-json-log-path) to send a copy of all Nix log messages (in JSON format) to a file or Unix domain socket.

doc/manual/source/release-notes-determinate/rl-3.0.0.md

@@ -3,3 +3,5 @@
 * Initial release of Determinate Nix.
 
 * Based on [upstream Nix 2.26.2](../release-notes/rl-2.26.md).
+
+* New setting `json-log-path` that sends a copy of all Nix log messages (in JSON format) to a file or Unix domain socket.

doc/manual/source/release-notes-determinate/rl-3.1.0.md

@@ -1,3 +1,3 @@
-# Release 3.1.0 (2025-??-??)
+# Release 3.1.0 (2025-03-27)
 
 * Based on [upstream Nix 2.27.1](../release-notes/rl-2.27.md).

src/libstore/build-result.cc

@@ -1,8 +1,49 @@
 #include "build-result.hh"
 
+#include <nlohmann/json.hpp>
+
 namespace nix {
 
 bool BuildResult::operator==(const BuildResult &) const noexcept = default;
 std::strong_ordering BuildResult::operator<=>(const BuildResult &) const noexcept = default;
 
+void to_json(nlohmann::json & json, const BuildResult & buildResult)
+{
+    json = nlohmann::json::object();
+    json["status"] = BuildResult::statusToString(buildResult.status);
+    if (buildResult.errorMsg != "")
+        json["errorMsg"] = buildResult.errorMsg;
+    if (buildResult.timesBuilt)
+        json["timesBuilt"] = buildResult.timesBuilt;
+    if (buildResult.isNonDeterministic)
+        json["isNonDeterministic"] = buildResult.isNonDeterministic;
+    if (buildResult.startTime)
+        json["startTime"] = buildResult.startTime;
+    if (buildResult.stopTime)
+        json["stopTime"] = buildResult.stopTime;
+}
+
+void to_json(nlohmann::json & json, const KeyedBuildResult & buildResult)
+{
+    to_json(json, (const BuildResult &) buildResult);
+    auto path = nlohmann::json::object();
+    std::visit(
+        overloaded{
+            [&](const DerivedPathOpaque & opaque) { path["opaque"] = opaque.path.to_string(); },
+            [&](const DerivedPathBuilt & drv) {
+                path["drvPath"] = drv.drvPath->getBaseStorePath().to_string();
+                path["outputs"] = drv.outputs;
+                auto outputs = nlohmann::json::object();
+                for (auto & [name, output] : buildResult.builtOutputs)
+                    outputs[name] = {
+                        {"path", output.outPath.to_string()},
+                        {"signatures", output.signatures},
+                    };
+                json["builtOutputs"] = std::move(outputs);
+            },
+        },
+        buildResult.path.raw());
+    json["path"] = std::move(path);
+}
+
 }

src/libstore/build-result.hh

@@ -8,6 +8,8 @@
 #include <chrono>
 #include <optional>
 
+#include <nlohmann/json_fwd.hpp>
+
 namespace nix {
 
 struct BuildResult
@@ -46,28 +48,32 @@ struct BuildResult
      */
     std::string errorMsg;
 
+    static std::string_view statusToString(Status status)
+    {
+        switch (status) {
+        case Built: return "Built";
+        case Substituted: return "Substituted";
+        case AlreadyValid: return "AlreadyValid";
+        case PermanentFailure: return "PermanentFailure";
+        case InputRejected: return "InputRejected";
+        case OutputRejected: return "OutputRejected";
+        case TransientFailure: return "TransientFailure";
+        case CachedFailure: return "CachedFailure";
+        case TimedOut: return "TimedOut";
+        case MiscFailure: return "MiscFailure";
+        case DependencyFailed: return "DependencyFailed";
+        case LogLimitExceeded: return "LogLimitExceeded";
+        case NotDeterministic: return "NotDeterministic";
+        case ResolvesToAlreadyValid: return "ResolvesToAlreadyValid";
+        case NoSubstituters: return "NoSubstituters";
+        default: return "Unknown";
+        };
+    }
+
     std::string toString() const {
-        auto strStatus = [&]() {
-            switch (status) {
-                case Built: return "Built";
-                case Substituted: return "Substituted";
-                case AlreadyValid: return "AlreadyValid";
-                case PermanentFailure: return "PermanentFailure";
-                case InputRejected: return "InputRejected";
-                case OutputRejected: return "OutputRejected";
-                case TransientFailure: return "TransientFailure";
-                case CachedFailure: return "CachedFailure";
-                case TimedOut: return "TimedOut";
-                case MiscFailure: return "MiscFailure";
-                case DependencyFailed: return "DependencyFailed";
-                case LogLimitExceeded: return "LogLimitExceeded";
-                case NotDeterministic: return "NotDeterministic";
-                case ResolvesToAlreadyValid: return "ResolvesToAlreadyValid";
-                case NoSubstituters: return "NoSubstituters";
-                default: return "Unknown";
-            };
-        }();
-        return strStatus + ((errorMsg == "") ? "" : " : " + errorMsg);
+        return
+            std::string(statusToString(status))
+            + ((errorMsg == "") ? "" : " : " + errorMsg);
     }
 
     /**
@@ -130,4 +136,7 @@ struct KeyedBuildResult : BuildResult
     { }
 };
 
+void to_json(nlohmann::json & json, const BuildResult & buildResult);
+void to_json(nlohmann::json & json, const KeyedBuildResult & buildResult);
+
 }

src/libstore/build/derivation-goal.cc

@@ -1540,6 +1540,14 @@ Goal::Done DerivationGoal::done(
         fs << worker.store.printStorePath(drvPath) << "\t" << buildResult.toString() << std::endl;
     }
 
+    logger->result(
+        act ? act->id : getCurActivity(),
+        resBuildResult,
+        nlohmann::json(
+            KeyedBuildResult(
+                buildResult,
+                DerivedPath::Built{.drvPath = makeConstantStorePathRef(drvPath), .outputs = wantedOutputs})));
+
     return amDone(buildResult.success() ? ecSuccess : ecFailed, std::move(ex));
 }
 

src/libstore/build/substitution-goal.cc

@@ -3,8 +3,11 @@
 #include "nar-info.hh"
 #include "finally.hh"
 #include "signals.hh"
+
 #include <coroutine>
 
+#include <nlohmann/json.hpp>
+
 namespace nix {
 
 PathSubstitutionGoal::PathSubstitutionGoal(const StorePath & storePath, Worker & worker, RepairFlag repair, std::optional<ContentAddress> ca)
@@ -35,6 +38,15 @@ Goal::Done PathSubstitutionGoal::done(
         debug(*errorMsg);
         buildResult.errorMsg = *errorMsg;
     }
+
+    logger->result(
+        getCurActivity(),
+        resBuildResult,
+        nlohmann::json(
+            KeyedBuildResult(
+                buildResult,
+                DerivedPath::Opaque{storePath})));
+
     return amDone(result);
 }
 

src/libstore/daemon.cc

@@ -15,6 +15,7 @@
 #include "derivations.hh"
 #include "args.hh"
 #include "git.hh"
+#include "logging.hh"
 
 #ifndef _WIN32 // TODO need graceful async exit support on Windows?
 # include "monitor-fd.hh"
@@ -1049,6 +1050,7 @@ void processConnection(
     if (!recursive) {
         prevLogger_ = std::move(logger);
         logger = std::move(tunnelLogger_);
+        applyJSONLogger();
     }
 
     unsigned int opCount = 0;

src/libstore/uds-remote-store.cc

@@ -84,9 +84,7 @@ ref<RemoteStore::Connection> UDSRemoteStore::openConnection()
     auto conn = make_ref<Connection>();
 
     /* Connect to a daemon that does the privileged work for us. */
-    conn->fd = createUnixDomainSocket();
-
-    nix::connect(toSocket(conn->fd.get()), path);
+    conn->fd = nix::connect(path);
 
     conn->from.fd = conn->fd.get();
     conn->to.fd = conn->fd.get();

src/libstore/unix/build/local-derivation-goal.cc

@@ -2654,6 +2654,12 @@ SingleDrvOutputs LocalDerivationGoal::registerOutputs()
                             worker.store.printStorePath(drvPath),
                             wanted.to_string(HashFormat::SRI, true),
                             got.to_string(HashFormat::SRI, true)));
+                    act->result(resHashMismatch,
+                        {
+                            {"storePath", worker.store.printStorePath(drvPath)},
+                            {"wanted", wanted},
+                            {"got", got},
+                        });
                 }
                 if (!newInfo0.references.empty()) {
                     auto numViolations = newInfo.references.size();

src/libutil/hash.cc

@@ -16,6 +16,8 @@
 #include <sys/stat.h>
 #include <fcntl.h>
 
+#include <nlohmann/json.hpp>
+
 #include <sodium.h>
 
 namespace nix {
@@ -467,4 +469,13 @@ std::string_view printHashAlgo(HashAlgorithm ha)
     }
 }
 
+void to_json(nlohmann::json & json, const Hash & hash)
+{
+    json = nlohmann::json::object(
+        {
+            {"algo", printHashAlgo(hash.algo)},
+            {"base16", hash.to_string(HashFormat::Base16, false)},
+        });
+}
+
 }

src/libutil/hash.hh

@@ -6,6 +6,8 @@
 #include "serialise.hh"
 #include "file-system.hh"
 
+#include <nlohmann/json_fwd.hpp>
+
 namespace nix {
 
 
@@ -210,6 +212,10 @@ std::optional<HashAlgorithm> parseHashAlgoOpt(std::string_view s);
  */
 std::string_view printHashAlgo(HashAlgorithm ha);
 
+/**
+ * Write a JSON serialisation of the format `{"algo":"<sha1|...>","base16":"<hex>"}`.
+ */
+void to_json(nlohmann::json & json, const Hash & hash);
 
 union Ctx;
 

src/libutil/logging.cc

@@ -6,6 +6,8 @@
 #include "config-global.hh"
 #include "source-path.hh"
 #include "position.hh"
+#include "sync.hh"
+#include "unix-domain-socket.hh"
 
 #include <atomic>
 #include <sstream>
@@ -181,8 +183,12 @@ void to_json(nlohmann::json & json, std::shared_ptr<Pos> pos)
 
 struct JSONLogger : Logger {
     Descriptor fd;
+    bool includeNixPrefix;
 
-    JSONLogger(Descriptor fd) : fd(fd) { }
+    JSONLogger(Descriptor fd, bool includeNixPrefix)
+        : fd(fd)
+        , includeNixPrefix(includeNixPrefix)
+    { }
 
     bool isVerbose() override {
         return true;
@@ -201,9 +207,33 @@ struct JSONLogger : Logger {
                 unreachable();
     }
 
+    struct State
+    {
+        bool enabled = true;
+    };
+
+    Sync<State> _state;
+
     void write(const nlohmann::json & json)
     {
-        writeLine(fd, "@nix " + json.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace));
+        auto line =
+            (includeNixPrefix ? "@nix " : "") +
+            json.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace);
+
+        /* Acquire a lock to prevent log messages from clobbering each
+           other. */
+        try {
+            auto state(_state.lock());
+            if (state->enabled)
+                writeLine(fd, line);
+        } catch (...) {
+            bool enabled = false;
+            std::swap(_state.lock()->enabled, enabled);
+            if (enabled) {
+                ignoreExceptionExceptInterrupt();
+                logger->warn("disabling JSON logger due to write errors");
+            }
+        }
     }
 
     void log(Verbosity lvl, std::string_view s) override
@@ -273,11 +303,61 @@ struct JSONLogger : Logger {
         addFields(json, fields);
         write(json);
     }
+
+    void result(ActivityId act, ResultType type, const nlohmann::json & j) override
+    {
+        nlohmann::json json;
+        json["action"] = "result";
+        json["id"] = act;
+        json["type"] = type;
+        json["payload"] = j;
+        write(json);
+    }
 };
 
-std::unique_ptr<Logger> makeJSONLogger(Descriptor fd)
+std::unique_ptr<Logger> makeJSONLogger(Descriptor fd, bool includeNixPrefix)
 {
-    return std::make_unique<JSONLogger>(fd);
+    return std::make_unique<JSONLogger>(fd, includeNixPrefix);
+}
+
+std::unique_ptr<Logger> makeJSONLogger(const std::filesystem::path & path, bool includeNixPrefix)
+{
+    struct JSONFileLogger : JSONLogger {
+        AutoCloseFD fd;
+
+        JSONFileLogger(AutoCloseFD && fd, bool includeNixPrefix)
+            : JSONLogger(fd.get(), includeNixPrefix)
+            , fd(std::move(fd))
+        { }
+    };
+
+    AutoCloseFD fd =
+        std::filesystem::is_socket(path)
+        ? connect(path)
+        : toDescriptor(open(path.c_str(), O_CREAT | O_APPEND | O_WRONLY, 0644));
+    if (!fd)
+        throw SysError("opening log file %1%", path);
+
+    return std::make_unique<JSONFileLogger>(std::move(fd), includeNixPrefix);
+}
+
+void applyJSONLogger()
+{
+    if (!loggerSettings.jsonLogPath.get().empty()) {
+        try {
+            std::vector<std::unique_ptr<Logger>> loggers;
+            loggers.push_back(makeJSONLogger(std::filesystem::path(loggerSettings.jsonLogPath.get()), false));
+            try {
+                logger = makeTeeLogger(std::move(logger), std::move(loggers));
+            } catch (...) {
+                // `logger` is now gone so give up.
+                abort();
+            }
+        } catch (...) {
+            ignoreExceptionExceptInterrupt();
+        }
+
+    }
 }
 
 static Logger::Fields getFields(nlohmann::json & json)

src/libutil/logging.hh

@@ -6,6 +6,8 @@
 #include "file-descriptor.hh"
 #include "finally.hh"
 
+#include <filesystem>
+
 #include <nlohmann/json_fwd.hpp>
 
 namespace nix {
@@ -37,6 +39,8 @@ typedef enum {
     resSetExpected = 106,
     resPostBuildLogLine = 107,
     resFetchStatus = 108,
+    resHashMismatch = 109,
+    resBuildResult = 110,
 } ResultType;
 
 typedef uint64_t ActivityId;
@@ -49,6 +53,14 @@ struct LoggerSettings : Config
           Whether Nix should print out a stack trace in case of Nix
           expression evaluation errors.
         )"};
+
+    Setting<Path> jsonLogPath{
+        this, "", "json-log-path",
+        R"(
+          A path to which JSON records of Nix's log output will be
+          written, in the same format as `--log-format internal-json`
+          (without the `@nix ` prefixes on each line).
+        )"};
 };
 
 extern LoggerSettings loggerSettings;
@@ -117,6 +129,8 @@ public:
 
     virtual void result(ActivityId act, ResultType type, const Fields & fields) { };
 
+    virtual void result(ActivityId act, ResultType type, const nlohmann::json & json) { };
+
     virtual void writeToStdout(std::string_view s);
 
     template<typename... Args>
@@ -169,6 +183,11 @@ struct Activity
     void setExpected(ActivityType type2, uint64_t expected) const
     { result(resSetExpected, type2, expected); }
 
+    void result(ResultType type, const nlohmann::json & json) const
+    {
+        logger.result(id, type, json);
+    }
+
     template<typename... Args>
     void result(ResultType type, const Args & ... args) const
     {
@@ -196,7 +215,20 @@ extern std::unique_ptr<Logger> logger;
 
 std::unique_ptr<Logger> makeSimpleLogger(bool printBuildLogs = true);
 
-std::unique_ptr<Logger> makeJSONLogger(Descriptor fd);
+/**
+ * Create a logger that sends log messages to `mainLogger` and the
+ * list of loggers in `extraLoggers`. Only `mainLogger` is used for
+ * writing to stdout and getting user input.
+ */
+std::unique_ptr<Logger> makeTeeLogger(
+    std::unique_ptr<Logger> mainLogger,
+    std::vector<std::unique_ptr<Logger>> && extraLoggers);
+
+std::unique_ptr<Logger> makeJSONLogger(Descriptor fd, bool includeNixPrefix = true);
+
+std::unique_ptr<Logger> makeJSONLogger(const std::filesystem::path & path, bool includeNixPrefix = true);
+
+void applyJSONLogger();
 
 /**
  * @param source A noun phrase describing the source of the message, e.g. "the builder".

src/libutil/meson.build

@@ -166,6 +166,7 @@ sources = files(
   'strings.cc',
   'suggestions.cc',
   'tarfile.cc',
+  'tee-logger.cc',
   'terminal.cc',
   'thread-pool.cc',
   'union-source-accessor.cc',

src/libutil/tee-logger.cc

@@ -0,0 +1,113 @@
+#include "logging.hh"
+
+namespace nix {
+
+struct TeeLogger : Logger
+{
+    std::vector<std::unique_ptr<Logger>> loggers;
+
+    TeeLogger(std::vector<std::unique_ptr<Logger>> && loggers)
+        : loggers(std::move(loggers))
+    {
+    }
+
+    void stop() override
+    {
+        for (auto & logger : loggers)
+            logger->stop();
+    };
+
+    void pause() override
+    {
+        for (auto & logger : loggers)
+            logger->pause();
+    };
+
+    void resume() override
+    {
+        for (auto & logger : loggers)
+            logger->resume();
+    };
+
+    void log(Verbosity lvl, std::string_view s) override
+    {
+        for (auto & logger : loggers)
+            logger->log(lvl, s);
+    }
+
+    void logEI(const ErrorInfo & ei) override
+    {
+        for (auto & logger : loggers)
+            logger->logEI(ei);
+    }
+
+    void startActivity(
+        ActivityId act,
+        Verbosity lvl,
+        ActivityType type,
+        const std::string & s,
+        const Fields & fields,
+        ActivityId parent) override
+    {
+        for (auto & logger : loggers)
+            logger->startActivity(act, lvl, type, s, fields, parent);
+    }
+
+    void stopActivity(ActivityId act) override
+    {
+        for (auto & logger : loggers)
+            logger->stopActivity(act);
+    }
+
+    void result(ActivityId act, ResultType type, const Fields & fields) override
+    {
+        for (auto & logger : loggers)
+            logger->result(act, type, fields);
+    }
+
+    void result(ActivityId act, ResultType type, const nlohmann::json & json) override
+    {
+        for (auto & logger : loggers)
+            logger->result(act, type, json);
+    }
+
+    void writeToStdout(std::string_view s) override
+    {
+        for (auto & logger : loggers) {
+            /* Let only the first logger write to stdout to avoid
+               duplication. This means that the first logger needs to
+               be the one managing stdout/stderr
+               (e.g. `ProgressBar`). */
+            logger->writeToStdout(s);
+            break;
+        }
+    }
+
+    std::optional<char> ask(std::string_view s) override
+    {
+        for (auto & logger : loggers) {
+            auto c = logger->ask(s);
+            if (c)
+                return c;
+        }
+        return std::nullopt;
+    }
+
+    void setPrintBuildLogs(bool printBuildLogs) override
+    {
+        for (auto & logger : loggers)
+            logger->setPrintBuildLogs(printBuildLogs);
+    }
+};
+
+std::unique_ptr<Logger>
+makeTeeLogger(std::unique_ptr<Logger> mainLogger, std::vector<std::unique_ptr<Logger>> && extraLoggers)
+{
+    std::vector<std::unique_ptr<Logger>> allLoggers;
+    allLoggers.push_back(std::move(mainLogger));
+    for (auto & l : extraLoggers)
+        allLoggers.push_back(std::move(l));
+    return std::make_unique<TeeLogger>(std::move(allLoggers));
+}
+
+}

src/libutil/unix-domain-socket.cc

@@ -114,4 +114,11 @@ void connect(Socket fd, const std::string & path)
     bindConnectProcHelper("connect", ::connect, fd, path);
 }
 
+AutoCloseFD connect(const std::filesystem::path & path)
+{
+    auto fd = createUnixDomainSocket();
+    nix::connect(toSocket(fd.get()), path);
+    return fd;
+}
+
 }

src/libutil/unix-domain-socket.hh

@@ -80,4 +80,9 @@ void bind(Socket fd, const std::string & path);
  */
 void connect(Socket fd, const std::string & path);
 
+/**
+ * Connect to a Unix domain socket.
+ */
+AutoCloseFD connect(const std::filesystem::path & path);
+
 }

src/nix/main.cc

@@ -5,6 +5,7 @@
 #include "eval.hh"
 #include "eval-settings.hh"
 #include "globals.hh"
+#include "config-global.hh"
 #include "legacy.hh"
 #include "shared.hh"
 #include "store-api.hh"
@@ -486,6 +487,8 @@ void mainWrapped(int argc, char * * argv)
         if (!args.helpRequested && !args.completions) throw;
     }
 
+    applyJSONLogger();
+
     if (args.helpRequested) {
         std::vector<std::string> subcommand;
         MultiCommand * command = &args;