Merge pull request #11921 from NixOS/log-json-tolerant

Make @nix json structured build log parsing warn instead of fail

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 {

src/libutil/logging.cc

@@ -280,61 +280,72 @@ static Logger::Fields getFields(nlohmann::json & json)
     return fields;
 }
 
-std::optional<nlohmann::json> parseJSONMessage(const std::string & msg)
+std::optional<nlohmann::json> 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<ActivityId, Activity> & activities,
-    bool trusted)
+    std::string_view source, bool trusted)
 {
-    std::string action = json["action"];
+    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));
+        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;
+    } catch (const nlohmann::json::exception &e) {
+        warn(
+            "Unable to handle a JSON message from %s: %s",
+            Uncolored(source),
+            e.what()
+        );
+        return false;
     }
-
-    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<ActivityId, Activity> & activities, bool trusted)
+    const Activity & act, std::map<ActivityId, Activity> & 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()

src/libutil/logging.hh

@@ -185,14 +185,25 @@ Logger * makeSimpleLogger(bool printBuildLogs = true);
 
 Logger * makeJSONLogger(Logger & prevLogger);
 
-std::optional<nlohmann::json> parseJSONMessage(const std::string & msg);
+/**
+ * @param source A noun phrase describing the source of the message, e.g. "the builder".
+ */
+std::optional<nlohmann::json> 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<ActivityId, Activity> & 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<ActivityId, Activity> & activities,
+    std::string_view source,
     bool trusted);
 
 /**

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";
 }

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

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
+  '';
+}