From 5ab7428a30f575a512dd32e7cd0f5b3b345e9c9d 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/loggers.cc | 7 +- src/libmain/loggers.hh | 1 + src/libutil/logging-diffs.cc | 238 +++++++++++++++++++++++++++++++++++ src/libutil/logging-diffs.hh | 51 ++++++++ src/libutil/meson.build | 2 + 5 files changed, 298 insertions(+), 1 deletion(-) create mode 100644 src/libutil/logging-diffs.cc create mode 100644 src/libutil/logging-diffs.hh diff --git a/src/libmain/loggers.cc b/src/libmain/loggers.cc index a4e0530c8f9..1e889b1d64b 100644 --- a/src/libmain/loggers.cc +++ b/src/libmain/loggers.cc @@ -1,5 +1,6 @@ -#include "loggers.hh" #include "environment-variables.hh" +#include "loggers.hh" +#include "logging-diffs.hh" #include "progress-bar.hh" namespace nix { @@ -13,6 +14,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") @@ -28,6 +31,8 @@ Logger * makeDefaultLogger() { return makeSimpleLogger(true); case LogFormat::internalJSON: return makeJSONLogger(*makeSimpleLogger(true)); + case LogFormat::diffs: + return makeDiffLogger(*makeSimpleLogger(true)); case LogFormat::bar: return makeProgressBar(); case LogFormat::barWithLogs: { diff --git a/src/libmain/loggers.hh b/src/libmain/loggers.hh index e5721420cb6..5516c31a328 100644 --- a/src/libmain/loggers.hh +++ b/src/libmain/loggers.hh @@ -9,6 +9,7 @@ enum class LogFormat { raw, rawWithLogs, internalJSON, + diffs, bar, barWithLogs, }; diff --git a/src/libutil/logging-diffs.cc b/src/libutil/logging-diffs.cc new file mode 100644 index 00000000000..722744d6abf --- /dev/null +++ b/src/libutil/logging-diffs.cc @@ -0,0 +1,238 @@ + +#include "config.hh" +#include "logging.hh" +#include "logging-diffs.hh" +#include "position.hh" +#include "sync.hh" +#include "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 { + Logger & prevLogger; + + Sync state; + json last_sent; + std::mutex lock; + std::atomic_bool exitPeriodicAction; + std::atomic_bool exited; + std::thread printerThread; + + DiffLogger(Logger & prevLogger) + : prevLogger(prevLogger) + , 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) + { + prevLogger.log(lvlError, 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))); + } + } +}; + +Logger * makeDiffLogger(Logger & prevLogger) +{ + return new DiffLogger(prevLogger); +} + +} diff --git a/src/libutil/logging-diffs.hh b/src/libutil/logging-diffs.hh new file mode 100644 index 00000000000..724b78aab6d --- /dev/null +++ b/src/libutil/logging-diffs.hh @@ -0,0 +1,51 @@ +#pragma once + +#include "types.hh" +#include "error.hh" +#include "config.hh" +#include "logging.hh" + +#include + +#include +#include +#include + +namespace nix { + +Logger * makeDiffLogger(Logger & prevLogger); + +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/meson.build b/src/libutil/meson.build index a6dc8639478..38749f00eb9 100644 --- a/src/libutil/meson.build +++ b/src/libutil/meson.build @@ -147,6 +147,7 @@ sources = files( 'hilite.cc', 'json-utils.cc', 'logging.cc', + 'logging-diffs.cc', 'memory-source-accessor.cc', 'position.cc', 'posix-source-accessor.cc', @@ -209,6 +210,7 @@ headers = [config_h] + files( 'json-impls.hh', 'json-utils.hh', 'logging.hh', + 'logging-diffs.cc', 'lru-cache.hh', 'memory-source-accessor.hh', 'muxable-pipe.hh',