libstore: more precise origin info for strange structured logs

Robert made these improvements on the PR that cherry-picked
e55cd3beea /
https://gerrit.lix.systems/c/lix/+/2057
from Lix into CppNix:
https://github.com/NixOS/nix/pull/11921

Push log source description out of libutil and report build hook @nix warning correctly

(cherry picked from commit 03d4bfd852dce9a050f984e887c887a43581796c)

test: Move unusual-logging to run only in logging test case

(cherry picked from commit 1421420e862434321c46511a3152016e443dd479)

Remove redundant warning: prefix from structured build log warning

(cherry picked from commit f3c722cab24f7a0de8c3573d25e91749f4f16234)
Change-Id: I7da99046f2a41b3c58e62351119bc89bcc25a703

lix/libstore/build/derivation-goal.cc

@@ -1215,7 +1215,7 @@ HookReply DerivationGoal::tryBuildHook()
                     throw;
                 }
             }();
-            if (handleJSONLogMessage(s, worker.act, worker.hook.instance->activities, true))
+            if (handleJSONLogMessage(s, worker.act, worker.hook.instance->activities, "the build hook", true))
                 ;
             else if (s.substr(0, 2) == "# ") {
                 reply = s.substr(2);
@@ -1440,9 +1440,9 @@ try {
 
         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 && logSink) {
@@ -1557,7 +1557,7 @@ DerivationGoal::handleChildStreams(InputStream & builderIn, InputStream * hookIn
 
 void DerivationGoal::flushLine()
 {
-    if (handleJSONLogMessage(currentLogLine, *act, builderActivities, false))
+    if (handleJSONLogMessage(currentLogLine, *act, builderActivities, "the derivation builder", false))
         ;
 
     else {

lix/libutil/logging-json.hh

@@ -10,14 +10,25 @@
 
 namespace nix {
 
-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);
 
 };

lix/libutil/logging.cc

@@ -290,20 +290,22 @@ 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 (!msg.starts_with("@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)
 {
     try {
         std::string action = json["action"];
@@ -339,7 +341,8 @@ bool handleJSONLogMessage(nlohmann::json & json,
         return true;
     } catch (nlohmann::json::exception &e) {
         warn(
-            "warning: Unable to handle a JSON message from the builder: %s",
+            "Unable to handle a JSON message from %s: %s",
+            Uncolored(source),
             e.what()
         );
         return false;
@@ -347,12 +350,12 @@ bool handleJSONLogMessage(nlohmann::json & json,
 }
 
 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()

tests/functional/dependencies.nix

@@ -32,17 +32,6 @@ let
     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";
@@ -52,7 +41,6 @@ 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";
 }

tests/functional/logging.sh

@@ -24,3 +24,6 @@ outp="$(nix-build -E \
 test -d "$outp"
 
 nix log "$outp"
+
+# 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:'

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