diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc index bf1a25db1f0..2ff0ef92f2c 100644 --- a/src/libstore/build/derivation-goal.cc +++ b/src/libstore/build/derivation-goal.cc @@ -1161,7 +1161,7 @@ HookReply DerivationGoal::tryBuildHook() throw; } }(); - if (handleJSONLogMessage(s, worker.act, worker.hook->activities, true)) + if (handleJSONLogMessage(s, worker.act, worker.hook->activities, "the build hook", true)) ; else if (s.substr(0, 2) == "# ") { reply = s.substr(2); @@ -1346,9 +1346,9 @@ void DerivationGoal::handleChildOutput(Descriptor fd, std::string_view data) if (hook && fd == hook->fromHook.readSide.get()) { for (auto c : data) if (c == '\n') { - auto json = parseJSONMessage(currentHookLine); + auto json = parseJSONMessage(currentHookLine, "the derivation builder"); if (json) { - auto s = handleJSONLogMessage(*json, worker.act, hook->activities, true); + auto s = handleJSONLogMessage(*json, worker.act, hook->activities, "the derivation builder", true); // ensure that logs from a builder using `ssh-ng://` as protocol // are also available to `nix log`. if (s && !isWrittenToLog && logSink) { @@ -1390,7 +1390,7 @@ void DerivationGoal::handleEOF(Descriptor fd) void DerivationGoal::flushLine() { - if (handleJSONLogMessage(currentLogLine, *act, builderActivities, false)) + if (handleJSONLogMessage(currentLogLine, *act, builderActivities, "the derivation builder", false)) ; else { diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc index 80c107ef538..a5add5565df 100644 --- a/src/libutil/logging.cc +++ b/src/libutil/logging.cc @@ -280,61 +280,72 @@ static Logger::Fields getFields(nlohmann::json & json) return fields; } -std::optional parseJSONMessage(const std::string & msg) +std::optional parseJSONMessage(const std::string & msg, std::string_view source) { if (!hasPrefix(msg, "@nix ")) return std::nullopt; try { return nlohmann::json::parse(std::string(msg, 5)); } catch (std::exception & e) { - printError("bad JSON log message from builder: %s", e.what()); + printError("bad JSON log message from %s: %s", + Uncolored(source), + e.what()); } return std::nullopt; } bool handleJSONLogMessage(nlohmann::json & json, const Activity & act, std::map & activities, - bool trusted) + std::string_view source, 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)); - } + try { + 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 == "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 == "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 == "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); - } + else if (action == "msg") { + std::string msg = json["msg"]; + logger->log((Verbosity) json["level"], msg); + } - return true; + return true; + } catch (const nlohmann::json::exception &e) { + warn( + "Unable to handle a JSON message from %s: %s", + Uncolored(source), + e.what() + ); + return false; + } } bool handleJSONLogMessage(const std::string & msg, - const Activity & act, std::map & activities, bool trusted) + const Activity & act, std::map & activities, std::string_view source, bool trusted) { - auto json = parseJSONMessage(msg); + auto json = parseJSONMessage(msg, source); if (!json) return false; - return handleJSONLogMessage(*json, act, activities, trusted); + return handleJSONLogMessage(*json, act, activities, source, trusted); } Activity::~Activity() diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh index 250f9209972..11e4033a59d 100644 --- a/src/libutil/logging.hh +++ b/src/libutil/logging.hh @@ -185,14 +185,25 @@ Logger * makeSimpleLogger(bool printBuildLogs = true); Logger * makeJSONLogger(Logger & prevLogger); -std::optional parseJSONMessage(const std::string & msg); +/** + * @param source A noun phrase describing the source of the message, e.g. "the builder". + */ +std::optional parseJSONMessage(const std::string & msg, std::string_view source); +/** + * @param source A noun phrase describing the source of the message, e.g. "the builder". + */ bool handleJSONLogMessage(nlohmann::json & json, const Activity & act, std::map & activities, + std::string_view source, bool trusted); +/** + * @param source A noun phrase describing the source of the message, e.g. "the builder". + */ bool handleJSONLogMessage(const std::string & msg, const Activity & act, std::map & activities, + std::string_view source, bool trusted); /** diff --git a/tests/functional/dependencies.nix b/tests/functional/dependencies.nix index be1a7ae9a6e..4ff29227fd3 100644 --- a/tests/functional/dependencies.nix +++ b/tests/functional/dependencies.nix @@ -1,7 +1,7 @@ { hashInvalidator ? "" }: with import ./config.nix; -let { +let input0 = mkDerivation { name = "dependencies-input-0"; @@ -33,16 +33,15 @@ let { outputHash = "1dq9p0hnm1y75q2x40fws5887bq1r840hzdxak0a9djbwvx0b16d"; }; - body = mkDerivation { - name = "dependencies-top"; - builder = ./dependencies.builder0.sh + "/FOOBAR/../."; - input1 = input1 + "/."; - input2 = "${input2}/."; - input1_drv = input1; - input2_drv = input2; - input0_drv = input0; - fod_input_drv = fod_input; - meta.description = "Random test package"; - }; - +in +mkDerivation { + name = "dependencies-top"; + builder = ./dependencies.builder0.sh + "/FOOBAR/../."; + input1 = input1 + "/."; + input2 = "${input2}/."; + input1_drv = input1; + input2_drv = input2; + input0_drv = input0; + fod_input_drv = fod_input; + meta.description = "Random test package"; } diff --git a/tests/functional/logging.sh b/tests/functional/logging.sh index c026ac9c211..ddb1913adf2 100755 --- a/tests/functional/logging.sh +++ b/tests/functional/logging.sh @@ -28,3 +28,8 @@ outp="$(nix-build -E \ test -d "$outp" nix log "$outp" + +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 diff --git a/tests/functional/logging/unusual-logging.nix b/tests/functional/logging/unusual-logging.nix new file mode 100644 index 00000000000..ddb8aa53010 --- /dev/null +++ b/tests/functional/logging/unusual-logging.nix @@ -0,0 +1,16 @@ +let + inherit (import ../config.nix) mkDerivation; +in +mkDerivation { + name = "unusual-logging"; + buildCommand = '' + { + echo "@nix 1" + echo "@nix {}" + echo '@nix {"action": null}' + echo '@nix {"action": 123}' + echo '@nix ][' + } >&$NIX_LOG_FD + touch $out + ''; +}