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.

Author: thomasjm

src/libmain/include/nix/main/loggers.hh

@@ -9,6 +9,7 @@ enum class LogFormat {
   raw,
   rawWithLogs,
   internalJSON,
+  diffs,
   bar,
   barWithLogs,
 };

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<Logger> makeDefaultLogger()
         return makeSimpleLogger(true);
     case LogFormat::internalJSON:
         return makeJSONLogger(getStandardError());
+    case LogFormat::diffs:
+        return makeDiffLogger(getStandardError());
     case LogFormat::bar:
         return makeProgressBar();
     case LogFormat::barWithLogs: {

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 <nlohmann/json.hpp>
+
+#include <list>
+#include <map>
+#include <optional>
+
+namespace nix {
+
+std::unique_ptr<Logger> 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<int> line;
+    std::optional<int> column;
+    std::optional<std::string> file;
+
+    std::optional<nlohmann::json> trace;
+
+    std::string msg;
+    std::string raw_msg;
+};
+
+struct NixBuildState {
+    std::map<ActivityId, ActivityState> activities;
+    std::list<NixMessage> messages;
+};
+
+}

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',

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 <atomic>
+#include <chrono>
+#include <iostream>
+#include <nlohmann/json.hpp>
+#include <thread>
+
+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> 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> 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<NixBuildState> 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<NixBuildState>::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<ActivityId, ActivityState>(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<int>(type)));
+        }
+    }
+};
+
+std::unique_ptr<Logger> makeDiffLogger(Descriptor fd)
+{
+    return std::make_unique<DiffLogger>(fd);
+}
+
+}

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',