libutil: handle json builder log messages with unexpected format

Before this change, expressions like:

with import <nixpkgs> {};
runCommand "foo" {} ''
  echo '@nix {}' >&$NIX_LOG_FD
''

would result in Lix crashing, because accessing nonexistent fields of
a JSON object throws an exception.

Rather than handling each field individually, we just catch JSON
exceptions wholesale. Since these log messages are an unusual
circumstance, log a warning when this happens.

Fixes #544.

Change-Id: Idc2d8acf6e37046b3ec212f42e29269163dca893

src/libutil/logging.cc

@@ -305,37 +305,45 @@ bool handleJSONLogMessage(nlohmann::json & json,
     const Activity & act, std::map<ActivityId, Activity> & activities,
     bool trusted)
 {
-    std::string action = json["action"];
+    try {
+        std::string action = json["action"];
 
-    if (action == "start") {
+        if (action == "start") {
-        auto type = (ActivityType) json["type"];
+            auto type = (ActivityType) json["type"];
-        if (trusted || type == actFileTransfer)
+            if (trusted || type == actFileTransfer)
-            activities.emplace(std::piecewise_construct,
+                activities.emplace(std::piecewise_construct,
-                std::forward_as_tuple(json["id"]),
+                    std::forward_as_tuple(json["id"]),
-                std::forward_as_tuple(*logger, (Verbosity) json["level"], type,
+                    std::forward_as_tuple(*logger, (Verbosity) json["level"], type,
-                    json["text"], getFields(json["fields"]), act.id));
+                        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 (nlohmann::json::exception &e) {
+        warn(
+            "warning: Unable to handle a JSON message from the builder: %s",
+            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,

tests/functional/dependencies.nix

@@ -31,6 +31,18 @@ let
     outputHashAlgo = "sha256";
     outputHash = "1dq9p0hnm1y75q2x40fws5887bq1r840hzdxak0a9djbwvx0b16d";
   };
+
+  unusual-logging = mkDerivation {
+    name = "unusual-logging";
+    buildCommand = ''
+      {
+        echo "@nix 1"
+        echo "@nix {}"
+        echo '@nix {"action": null}'
+      } >&$NIX_LOG_FD
+      touch $out
+    '';
+  };
 in
 mkDerivation {
   name = "dependencies-top";
@@ -40,6 +52,7 @@ mkDerivation {
   input1_drv = input1;
   input2_drv = input2;
   input0_drv = input0;
+  unusual_logging_drv = unusual-logging;
   fod_input_drv = fod_input;
   meta.description = "Random test package";
 }