From 0981c510456e8fdee8bc449cc79f8724a1b7f09c Mon Sep 17 00:00:00 2001 From: Tom McLaughlin Date: Sun, 27 Feb 2022 05:50:36 -0800 Subject: [PATCH] New logger: JSON diffs This is a new logger that outputs the build state in the form of a series of RFC 6902 JSON patches. The first line it outputs is an empty object, and then it periodically outputs diffs which transform the initial object until the build completes. This is used to efficiently support downstream tools which want to consume Nix build information and display it in a UI. --- src/libmain/include/nix/main/loggers.hh | 1 + src/libmain/loggers.cc | 5 + src/libutil/include/nix/util/logging-diffs.hh | 51 ++++ src/libutil/include/nix/util/meson.build | 1 + src/libutil/logging-diffs.cc | 238 ++++++++++++++++++ src/libutil/meson.build | 1 + 6 files changed, 297 insertions(+) create mode 100644 src/libutil/include/nix/util/logging-diffs.hh create mode 100644 src/libutil/logging-diffs.cc diff --git a/src/libmain/include/nix/main/loggers.hh b/src/libmain/include/nix/main/loggers.hh index 061b4a32a..76c76c960 100644 --- a/src/libmain/include/nix/main/loggers.hh +++ b/src/libmain/include/nix/main/loggers.hh @@ -9,6 +9,7 @@ enum class LogFormat { raw, rawWithLogs, internalJSON, + diffs, bar, barWithLogs, }; diff --git a/src/libmain/loggers.cc b/src/libmain/loggers.cc index c78e49b63..7b4774535 100644 --- a/src/libmain/loggers.cc +++ b/src/libmain/loggers.cc @@ -1,4 +1,5 @@ #include "nix/main/loggers.hh" +#include "nix/util/logging-diffs.hh" #include "nix/util/environment-variables.hh" #include "nix/main/progress-bar.hh" @@ -14,6 +15,8 @@ LogFormat parseLogFormat(const std::string & logFormatStr) return LogFormat::rawWithLogs; else if (logFormatStr == "internal-json") return LogFormat::internalJSON; + else if (logFormatStr == "diffs") + return LogFormat::diffs; else if (logFormatStr == "bar") return LogFormat::bar; else if (logFormatStr == "bar-with-logs") @@ -30,6 +33,8 @@ std::unique_ptr makeDefaultLogger() return makeSimpleLogger(true); case LogFormat::internalJSON: return makeJSONLogger(getStandardError()); + case LogFormat::diffs: + return makeDiffLogger(getStandardError()); case LogFormat::bar: return makeProgressBar(); case LogFormat::barWithLogs: { diff --git a/src/libutil/include/nix/util/logging-diffs.hh b/src/libutil/include/nix/util/logging-diffs.hh new file mode 100644 index 000000000..18d1d37a1 --- /dev/null +++ b/src/libutil/include/nix/util/logging-diffs.hh @@ -0,0 +1,51 @@ +#pragma once + +#include "nix/util/types.hh" +#include "nix/util/error.hh" +#include "nix/util/configuration.hh" +#include "nix/util/logging.hh" + +#include + +#include +#include +#include + +namespace nix { + +std::unique_ptr makeDiffLogger(Descriptor fd); + +struct ActivityState { + bool isComplete; + ActivityType type; + std::string text; + Logger::Fields fields; + ActivityId parent; + + ActivityState(ActivityType _type, const std::string _text, const Logger::Fields &_fields, ActivityId _parent): + isComplete(false), + type(_type), + text(_text), + fields(_fields), + parent(_parent) { } +}; + +struct NixMessage { + int level; + + std::optional line; + std::optional column; + std::optional file; + + std::optional trace; + + std::string msg; + std::string raw_msg; +}; + +struct NixBuildState { + std::map activities; + std::list messages; +}; + +} diff --git a/src/libutil/include/nix/util/meson.build b/src/libutil/include/nix/util/meson.build index e30b8dacd..498fd8093 100644 --- a/src/libutil/include/nix/util/meson.build +++ b/src/libutil/include/nix/util/meson.build @@ -41,6 +41,7 @@ headers = files( 'json-impls.hh', 'json-utils.hh', 'logging.hh', + 'logging-diffs.hh', 'lru-cache.hh', 'memory-source-accessor.hh', 'muxable-pipe.hh', diff --git a/src/libutil/logging-diffs.cc b/src/libutil/logging-diffs.cc new file mode 100644 index 000000000..7420d0c52 --- /dev/null +++ b/src/libutil/logging-diffs.cc @@ -0,0 +1,238 @@ + +#include "nix/util/configuration.hh" +#include "nix/util/logging.hh" +#include "nix/util/logging-diffs.hh" +#include "nix/util/position.hh" +#include "nix/util/sync.hh" +#include "nix/util/util.hh" + +#include +#include +#include +#include +#include + +using json = nlohmann::json; + +namespace nix { + +void addFields(json & json, const Logger::Fields & fields) +{ + if (fields.empty()) return; + auto & arr = json["fields"] = json::array(); + for (auto & f : fields) + if (f.type == Logger::Field::tInt) + arr.push_back(f.i); + else if (f.type == Logger::Field::tString) + arr.push_back(f.s); + else + abort(); +} + +void to_json(json & j, const NixMessage & m) +{ + j = json{ {"level", m.level} }; + + if (m.line.has_value()) j["line"] = m.line.value(); + if (m.column.has_value()) j["column"] = m.column.value(); + if (m.file.has_value()) j["file"] = m.file.value(); + + if (m.trace.has_value()) j["trace"] = m.trace.value(); + + if (!m.msg.empty()) j["msg"] = m.msg; + if (!m.raw_msg.empty()) j["raw_msg"] = m.raw_msg; +} + +void to_json(json & j, const ActivityState & as) +{ + j = json{ {"is_complete", as.isComplete}, {"type", as.type}, {"text", as.text} }; + addFields(j, as.fields); +} + +void to_json(json & j, const NixBuildState & s) +{ + j = json{ {"messages", s.messages} }; + + j["activities"] = json(json::value_t::object); + for (const auto& [key, value] : s.activities) { + j["activities"][std::to_string(key)] = value; + } +} + +static void addPosToMessage(NixMessage & msg, std::shared_ptr pos) +{ + if (pos) { + msg.line = pos->line; + msg.column = pos->column; + std::ostringstream str; + pos->print(str, true); + msg.file = str.str(); + } else { + msg.line = std::nullopt; + msg.column = std::nullopt; + msg.file = std::nullopt; + } +} + +static void posToJson(json & json, std::shared_ptr pos) +{ + if (pos) { + json["line"] = pos->line; + json["column"] = pos->column; + std::ostringstream str; + pos->print(str, true); + json["file"] = str.str(); + } else { + json["line"] = nullptr; + json["column"] = nullptr; + json["file"] = nullptr; + } +} + +struct DiffLogger : Logger { + Descriptor fd; + + Sync state; + json last_sent; + std::mutex lock; + std::atomic_bool exitPeriodicAction; + std::atomic_bool exited; + std::thread printerThread; + + DiffLogger(Descriptor fd) + : fd(fd) + , last_sent(nullptr) + , exitPeriodicAction(false) + , exited(false) + , printerThread(std::thread(&DiffLogger::periodicAction, this)) + { } + + // Note: tried to move the contents of the stop() fn to ~DiffLogger, but couldn't get + // it to run. + + ~DiffLogger() { + this->stop(); + } + + void stop() override { + // Make stop() idempotent + if (this->exitPeriodicAction) return; + + this->exitPeriodicAction = true; + this->printerThread.join(); + sendLatestIfNecessary(); + this->exited = true; + } + + void periodicAction() { + // Send initial value as a normal value + { + auto state_(state.lock()); + write(*state_); + this->last_sent = *state_; + } + + while (true) { + if (this->exitPeriodicAction) break; + + sendLatestIfNecessary(); + + std::this_thread::sleep_for(std::chrono::milliseconds(300)); + } + } + + void sendLatestIfNecessary() { + auto state_(state.lock()); + this->sendLatestIfNecessaryUnlocked(state_); + } + + void sendLatestIfNecessaryUnlocked(Sync::WriteLock & _state) { + if (this->last_sent == *_state) return; + + write(json::diff(this->last_sent, *_state)); + this->last_sent = *_state; + } + + bool isVerbose() override { + return true; + } + + void write(const json & json) + { + writeLine(fd, json.dump(-1, ' ', false, json::error_handler_t::replace)); + } + + void log(Verbosity lvl, std::string_view s) override + { + auto state_(state.lock()); + NixMessage msg; + msg.msg = s; + state_->messages.push_back(msg); + + // Not sure why, but sometimes log messages happen after stop() is called + if (this->exited) sendLatestIfNecessaryUnlocked(state_); + } + + void logEI(const ErrorInfo & ei) override + { + NixMessage msg; + + std::ostringstream oss; + showErrorInfo(oss, ei, loggerSettings.showTrace.get()); + + msg.level = ei.level; + msg.msg = oss.str(); + msg.raw_msg = ei.msg.str(); + + addPosToMessage(msg, ei.pos); + + if (loggerSettings.showTrace.get() && !ei.traces.empty()) { + json traces = json::array(); + for (auto iter = ei.traces.rbegin(); iter != ei.traces.rend(); ++iter) { + json stackFrame; + stackFrame["raw_msg"] = iter->hint.str(); + posToJson(stackFrame, iter->pos); + traces.push_back(stackFrame); + } + + msg.trace = traces; + } + + auto state_(state.lock()); + state_->messages.push_back(msg); + + // Not sure why, but sometimes log messages happen after stop() is called + if (this->exited) sendLatestIfNecessaryUnlocked(state_); + } + + void startActivity(ActivityId act, Verbosity lvl, ActivityType type, + const std::string & s, const Fields & fields, ActivityId parent) override + { + ActivityState as(type, s, fields, parent); + auto state_(state.lock()); + state_->activities.insert(std::pair(act, as)); + } + + void stopActivity(ActivityId act) override + { + auto state_(state.lock()); + try { state_->activities.at(act).isComplete = true; } + catch (const std::out_of_range& oor) { } + } + + void result(ActivityId act, ResultType type, const Fields & fields) override + { + auto state_(state.lock()); + try { state_->activities.at(act).fields = fields; } + catch (const std::out_of_range& oor) { + Logger::writeToStdout("Failed to look up result of type " + std::to_string(static_cast(type))); + } + } +}; + +std::unique_ptr makeDiffLogger(Descriptor fd) +{ + return std::make_unique(fd); +} + +} diff --git a/src/libutil/meson.build b/src/libutil/meson.build index 782c361e0..6847d7125 100644 --- a/src/libutil/meson.build +++ b/src/libutil/meson.build @@ -131,6 +131,7 @@ sources = [config_priv_h] + files( 'hilite.cc', 'json-utils.cc', 'logging.cc', + 'logging-diffs.cc', 'memory-source-accessor.cc', 'mounted-source-accessor.cc', 'position.cc',