From 6f2ec5f359d9bd312ec52e5a89cd29642ddd2380 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Fri, 11 Apr 2025 16:11:57 +0200 Subject: [PATCH 1/2] Add convenience function for connecting to a Unix domain socket --- src/libstore/uds-remote-store.cc | 4 +--- src/libutil/include/nix/util/unix-domain-socket.hh | 7 +++++++ src/libutil/unix-domain-socket.cc | 7 +++++++ 3 files changed, 15 insertions(+), 3 deletions(-) diff --git a/src/libstore/uds-remote-store.cc b/src/libstore/uds-remote-store.cc index 3c1657d1522..b58dd4783e1 100644 --- a/src/libstore/uds-remote-store.cc +++ b/src/libstore/uds-remote-store.cc @@ -84,9 +84,7 @@ ref UDSRemoteStore::openConnection() auto conn = make_ref(); /* 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(); diff --git a/src/libutil/include/nix/util/unix-domain-socket.hh b/src/libutil/include/nix/util/unix-domain-socket.hh index 704999ec1d8..6885d740b12 100644 --- a/src/libutil/include/nix/util/unix-domain-socket.hh +++ b/src/libutil/include/nix/util/unix-domain-socket.hh @@ -9,6 +9,8 @@ #endif #include +#include + namespace nix { /** @@ -80,4 +82,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); + } diff --git a/src/libutil/unix-domain-socket.cc b/src/libutil/unix-domain-socket.cc index 8722c8f0557..0e8c21d668f 100644 --- a/src/libutil/unix-domain-socket.cc +++ b/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; +} + } From eee841ae81450e4b23cee99f2ad48060903f39c4 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Fri, 11 Apr 2025 16:45:59 +0200 Subject: [PATCH 2/2] 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). --- doc/manual/rl-next/json-logger.md | 6 ++ src/libstore/daemon.cc | 2 + src/libutil/include/nix/util/logging.hh | 25 +++++- src/libutil/logging.cc | 68 +++++++++++++-- src/libutil/meson.build | 1 + src/libutil/tee-logger.cc | 107 ++++++++++++++++++++++++ src/nix/main.cc | 2 + tests/functional/logging.sh | 9 ++ 8 files changed, 213 insertions(+), 7 deletions(-) create mode 100644 doc/manual/rl-next/json-logger.md create mode 100644 src/libutil/tee-logger.cc diff --git a/doc/manual/rl-next/json-logger.md b/doc/manual/rl-next/json-logger.md new file mode 100644 index 00000000000..867b5d8b3fa --- /dev/null +++ b/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. diff --git a/src/libstore/daemon.cc b/src/libstore/daemon.cc index 8f751427342..dfc068bc775 100644 --- a/src/libstore/daemon.cc +++ b/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; diff --git a/src/libutil/include/nix/util/logging.hh b/src/libutil/include/nix/util/logging.hh index 9210229bf26..f2064b74d8a 100644 --- a/src/libutil/include/nix/util/logging.hh +++ b/src/libutil/include/nix/util/logging.hh @@ -6,6 +6,8 @@ #include "nix/util/file-descriptor.hh" #include "nix/util/finally.hh" +#include + #include 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 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; std::unique_ptr makeSimpleLogger(bool printBuildLogs = true); -std::unique_ptr 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 makeTeeLogger( + std::unique_ptr mainLogger, + std::vector> && extraLoggers); + +std::unique_ptr makeJSONLogger(Descriptor fd, bool includeNixPrefix = true); + +std::unique_ptr 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". diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc index 1d0d3fa2d70..a328a5c73e3 100644 --- a/src/libutil/logging.cc +++ b/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 #include @@ -182,8 +183,12 @@ void to_json(nlohmann::json & json, std::shared_ptr 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,6 +209,7 @@ struct JSONLogger : Logger { struct State { + bool enabled = true; }; Sync _state; @@ -211,13 +217,23 @@ struct JSONLogger : Logger { 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 makeJSONLogger(Descriptor fd) +std::unique_ptr makeJSONLogger(Descriptor fd, bool includeNixPrefix) +{ + return std::make_unique(fd, includeNixPrefix); +} + +std::unique_ptr 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(std::move(fd), includeNixPrefix); +} + +void applyJSONLogger() { - return std::make_unique(fd); + if (!loggerSettings.jsonLogPath.get().empty()) { + try { + std::vector> 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) diff --git a/src/libutil/meson.build b/src/libutil/meson.build index 782c361e00f..a9d8a5eb0df 100644 --- a/src/libutil/meson.build +++ b/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', diff --git a/src/libutil/tee-logger.cc b/src/libutil/tee-logger.cc new file mode 100644 index 00000000000..55334a821fb --- /dev/null +++ b/src/libutil/tee-logger.cc @@ -0,0 +1,107 @@ +#include "nix/util/logging.hh" + +namespace nix { + +struct TeeLogger : Logger +{ + std::vector> loggers; + + TeeLogger(std::vector> && 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 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 +makeTeeLogger(std::unique_ptr mainLogger, std::vector> && extraLoggers) +{ + std::vector> allLoggers; + allLoggers.push_back(std::move(mainLogger)); + for (auto & l : extraLoggers) + allLoggers.push_back(std::move(l)); + return std::make_unique(std::move(allLoggers)); +} + +} diff --git a/src/nix/main.cc b/src/nix/main.cc index a2c9dcf68da..008325f7f0b 100644 --- a/src/nix/main.cc +++ b/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 subcommand; MultiCommand * command = &args; diff --git a/tests/functional/logging.sh b/tests/functional/logging.sh index ddb1913adf2..83df9a45d7d 100755 --- a/tests/functional/logging.sh +++ b/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