From cd92ea588504db697103d3ff56166fe61e6da131 Mon Sep 17 00:00:00 2001 From: Maximilian Bosch Date: Sat, 19 Feb 2022 22:34:50 +0100 Subject: [PATCH] libstore/derivation-goal: avoid double-parsing of JSON messages To avoid that JSON messages are parsed twice in case of remote builds with `ssh-ng://`, I split up the original `handleJSONLogMessage` into three parts: * `parseJSONMessage(const std::string&)` checks if it's a message in the form of `@nix {...}` and tries to parse it (and prints an error if the parsing fails). * `handleJSONLogMessage(nlohmann::json&, ...)` reads the fields from the message and passes them to the logger. * `handleJSONLogMessage(const std::string&, ...)` behaves as before, but uses the two functions mentioned above as implementation. In case of `ssh-ng://`-logs the first two methods are invoked manually. --- src/libstore/build/derivation-goal.cc | 14 +++-- src/libutil/logging.cc | 84 +++++++++++++++------------ src/libutil/logging.hh | 8 +++ 3 files changed, 64 insertions(+), 42 deletions(-) diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc index ef1135601..c49be5e79 100644 --- a/src/libstore/build/derivation-goal.cc +++ b/src/libstore/build/derivation-goal.cc @@ -1207,12 +1207,14 @@ void DerivationGoal::handleChildOutput(int fd, std::string_view data) if (hook && fd == hook->fromHook.readSide.get()) { for (auto c : data) if (c == '\n') { - auto s = handleJSONLogMessage(currentHookLine, worker.act, hook->activities, true); - if (s && !isWrittenToLog && logSink) { - auto json = nlohmann::json::parse(std::string(currentHookLine, 5)); - if (json["type"] == resBuildLogLine) { - auto f = json["fields"]; - (*logSink)((f.size() > 0 ? f.at(0).get() : "") + "\n"); + auto json = parseJSONMessage(currentHookLine); + if (json) { + auto s = handleJSONLogMessage(*json, worker.act, hook->activities, true); + if (s && !isWrittenToLog && logSink) { + if ((*json)["type"] == resBuildLogLine) { + auto f = (*json)["fields"]; + (*logSink)((f.size() > 0 ? f.at(0).get() : "") + "\n"); + } } } currentHookLine.clear(); diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc index 74ee2f063..cb2b15b41 100644 --- a/src/libutil/logging.cc +++ b/src/libutil/logging.cc @@ -266,51 +266,63 @@ static Logger::Fields getFields(nlohmann::json & json) return fields; } -bool handleJSONLogMessage(const std::string & msg, - const Activity & act, std::map & activities, bool trusted) +std::optional parseJSONMessage(const std::string & msg) { - if (!hasPrefix(msg, "@nix ")) return false; - + if (!hasPrefix(msg, "@nix ")) return std::nullopt; try { - auto json = nlohmann::json::parse(std::string(msg, 5)); - - std::string action = json["action"]; - - if (action == "start") { - auto type = (ActivityType) json["type"]; - if (trusted || type == actFileTransfer) - activities.emplace(std::piecewise_construct, - std::forward_as_tuple(json["id"]), - std::forward_as_tuple(*logger, (Verbosity) json["level"], type, - json["text"], getFields(json["fields"]), act.id)); - } - - else if (action == "stop") - activities.erase((ActivityId) json["id"]); - - else if (action == "result") { - auto i = activities.find((ActivityId) json["id"]); - if (i != activities.end()) - i->second.result((ResultType) json["type"], getFields(json["fields"])); - } - - else if (action == "setPhase") { - std::string phase = json["phase"]; - act.result(resSetPhase, phase); - } - - else if (action == "msg") { - std::string msg = json["msg"]; - logger->log((Verbosity) json["level"], msg); - } - + return nlohmann::json::parse(std::string(msg, 5)); } catch (std::exception & e) { printError("bad JSON log message from builder: %s", e.what()); } + return std::nullopt; +} + +bool handleJSONLogMessage(nlohmann::json & json, + const Activity & act, std::map & activities, + bool trusted) +{ + std::string action = json["action"]; + + if (action == "start") { + auto type = (ActivityType) json["type"]; + if (trusted || type == actFileTransfer) + activities.emplace(std::piecewise_construct, + std::forward_as_tuple(json["id"]), + std::forward_as_tuple(*logger, (Verbosity) json["level"], type, + json["text"], getFields(json["fields"]), act.id)); + } + + else if (action == "stop") + activities.erase((ActivityId) json["id"]); + + else if (action == "result") { + auto i = activities.find((ActivityId) json["id"]); + if (i != activities.end()) + i->second.result((ResultType) json["type"], getFields(json["fields"])); + } + + else if (action == "setPhase") { + std::string phase = json["phase"]; + act.result(resSetPhase, phase); + } + + else if (action == "msg") { + std::string msg = json["msg"]; + logger->log((Verbosity) json["level"], msg); + } return true; } +bool handleJSONLogMessage(const std::string & msg, + const Activity & act, std::map & activities, bool trusted) +{ + auto json = parseJSONMessage(msg); + if (!json) return false; + + return handleJSONLogMessage(*json, act, activities, trusted); +} + Activity::~Activity() { try { diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh index bd28036ae..9ab2091c7 100644 --- a/src/libutil/logging.hh +++ b/src/libutil/logging.hh @@ -4,6 +4,8 @@ #include "error.hh" #include "config.hh" +#include + namespace nix { typedef enum { @@ -166,6 +168,12 @@ Logger * makeSimpleLogger(bool printBuildLogs = true); Logger * makeJSONLogger(Logger & prevLogger); +std::optional parseJSONMessage(const std::string & msg); + +bool handleJSONLogMessage(nlohmann::json & json, + const Activity & act, std::map & activities, + bool trusted); + bool handleJSONLogMessage(const std::string & msg, const Activity & act, std::map & activities, bool trusted);