Add json-log-path setting

This setting specifies a path (which can be a regular file or Unix
domain socket) that receives a copy of all Nix log messages (in JSON
format).

Author: edolstra

doc/manual/rl-next/json-logger.md

@@ -0,0 +1,6 @@
+---
+synopsis: "`json-log-path` setting"
+prs: [13003]
+---
+
+New setting `json-log-path` that sends a copy of all Nix log messages (in JSON format) to a file or Unix domain socket.

src/libstore/daemon.cc

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

src/libutil/include/nix/util/logging.hh

@@ -6,6 +6,8 @@
 #include "nix/util/file-descriptor.hh"
 #include "nix/util/finally.hh"
 
+#include <filesystem>
+
 #include <nlohmann/json_fwd.hpp>
 
 namespace nix {
@@ -49,6 +51,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;
@@ -196,7 +206,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/logging.cc

@@ -7,6 +7,7 @@
 #include "nix/util/source-path.hh"
 #include "nix/util/position.hh"
 #include "nix/util/sync.hh"
+#include "nix/util/unix-domain-socket.hh"
 
 #include <atomic>
 #include <sstream>
@@ -182,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;
@@ -204,20 +209,31 @@ struct JSONLogger : Logger {
 
     struct State
     {
+        bool enabled = true;
     };
 
     Sync<State> _state;
 
     void write(const nlohmann::json & json)
     {
         auto line =
-            "@nix " +
+            (includeNixPrefix ? "@nix " : "") +
             json.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace);
 
         /* Acquire a lock to prevent log messages from clobbering each
            other. */
-        auto state(_state.lock());
-        writeLine(fd, line);
+        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
@@ -289,9 +305,49 @@ struct JSONLogger : Logger {
     }
 };
 
-std::unique_ptr<Logger> makeJSONLogger(Descriptor fd)
+std::unique_ptr<Logger> makeJSONLogger(Descriptor fd, bool includeNixPrefix)
+{
+    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()
 {
-    return std::make_unique<JSONLogger>(fd);
+    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/meson.build

@@ -146,6 +146,7 @@ sources = [config_priv_h] + 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,107 @@
+#include "nix/util/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 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/nix/main.cc

@@ -493,6 +493,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;

tests/functional/logging.sh

@@ -33,3 +33,12 @@ if isDaemonNewer "2.26"; then
     # Build works despite ill-formed structured build log entries.
     expectStderr 0 nix build -f ./logging/unusual-logging.nix --no-link | grepQuiet 'warning: Unable to handle a JSON message from the derivation builder:'
 fi
+
+# Test json-log-path.
+if [[ "$NIX_REMOTE" != "daemon" ]]; then
+    clearStore
+    nix build -vv --file dependencies.nix --no-link --json-log-path "$TEST_ROOT/log.json" 2>&1 | grepQuiet 'building.*dependencies-top.drv'
+    jq < "$TEST_ROOT/log.json"
+    grep '{"action":"start","fields":\[".*-dependencies-top.drv","",1,1\],"id":.*,"level":3,"parent":0' "$TEST_ROOT/log.json" >&2
+    (( $(grep '{"action":"msg","level":5,"msg":"executing builder .*"}' "$TEST_ROOT/log.json" | wc -l) == 5 ))
+fi