ssh-ng: also store build logs to make them accessible by nix log

src/libstore/build/derivation-goal.cc

@@ -1175,10 +1175,11 @@ bool DerivationGoal::isReadDesc(int fd)
     return fd == hook->builderOut.readSide.get();
 }
 
-
 void DerivationGoal::handleChildOutput(int fd, std::string_view data)
 {
-    if (isReadDesc(fd))
+    // local & `ssh://`-builds are dealt with here.
+    auto isWrittenToLog = isReadDesc(fd);
+    if (isWrittenToLog)
     {
         logSize += data.size();
         if (settings.maxLogSize && logSize > settings.maxLogSize) {
@@ -1207,7 +1208,16 @@ void DerivationGoal::handleChildOutput(int fd, std::string_view data)
     if (hook && fd == hook->fromHook.readSide.get()) {
         for (auto c : data)
             if (c == '\n') {
-                handleJSONLogMessage(currentHookLine, worker.act, hook->activities, true);
+                auto json = parseJSONMessage(currentHookLine);
+                if (json) {
+                    auto s = handleJSONLogMessage(*json, worker.act, hook->activities, true);
+                    // ensure that logs from a builder using `ssh-ng://` as protocol
+                    // are also available to `nix log`.
+                    if (s && !isWrittenToLog && logSink && (*json)["type"] == resBuildLogLine) {
+                        auto f = (*json)["fields"];
+                        (*logSink)((f.size() > 0 ? f.at(0).get<std::string>() : "") + "\n");
+                    }
+                }
                 currentHookLine.clear();
             } else
                 currentHookLine += c;

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<ActivityId, Activity> & activities, bool trusted)
+std::optional<nlohmann::json> 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));
-        }
+        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;
+}
 
-        else if (action == "stop")
-            activities.erase((ActivityId) json["id"]);
+bool handleJSONLogMessage(nlohmann::json & json,
+    const Activity & act, std::map<ActivityId, Activity> & 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 == "result") {
-            auto i = activities.find((ActivityId) json["id"]);
-            if (i != activities.end())
-                i->second.result((ResultType) json["type"], getFields(json["fields"]));
-        }
+    else if (action == "stop")
+        activities.erase((ActivityId) json["id"]);
 
-        else if (action == "setPhase") {
-            std::string phase = json["phase"];
-            act.result(resSetPhase, phase);
-        }
+    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 == "msg") {
-            std::string msg = json["msg"];
-            logger->log((Verbosity) json["level"], msg);
-        }
+    else if (action == "setPhase") {
+        std::string phase = json["phase"];
+        act.result(resSetPhase, phase);
+    }
 
-    } catch (std::exception & e) {
-        printError("bad JSON log message from builder: %s", e.what());
+    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)
+{
+    auto json = parseJSONMessage(msg);
+    if (!json) return false;
+
+    return handleJSONLogMessage(*json, act, activities, trusted);
+}
+
 Activity::~Activity()
 {
     try {

src/libutil/logging.hh

@@ -4,6 +4,8 @@
 #include "error.hh"
 #include "config.hh"
 
+#include <nlohmann/json_fwd.hpp>
+
 namespace nix {
 
 typedef enum {
@@ -166,6 +168,12 @@ Logger * makeSimpleLogger(bool printBuildLogs = true);
 
 Logger * makeJSONLogger(Logger & prevLogger);
 
+std::optional<nlohmann::json> parseJSONMessage(const std::string & msg);
+
+bool handleJSONLogMessage(nlohmann::json & json,
+    const Activity & act, std::map<ActivityId, Activity> & activities,
+    bool trusted);
+
 bool handleJSONLogMessage(const std::string & msg,
     const Activity & act, std::map<ActivityId, Activity> & activities,
     bool trusted);

tests/build-hook-ca-fixed.nix

@@ -11,21 +11,21 @@ let
       args = ["sh" "-e" args.builder or (builtins.toFile "builder-${args.name}.sh" "if [ -e .attrs.sh ]; then source .attrs.sh; fi; eval \"$buildCommand\"")];
       outputHashMode = "recursive";
       outputHashAlgo = "sha256";
-    } // removeAttrs args ["builder" "meta"])
-    // { meta = args.meta or {}; };
+    } // removeAttrs args ["builder" "meta" "passthru"])
+    // { meta = args.meta or {}; passthru = args.passthru or {}; };
 
   input1 = mkDerivation {
     shell = busybox;
     name = "build-remote-input-1";
-    buildCommand = "echo FOO > $out";
+    buildCommand = "echo hi-input1; echo FOO > $out";
     requiredSystemFeatures = ["foo"];
     outputHash = "sha256-FePFYIlMuycIXPZbWi7LGEiMmZSX9FMbaQenWBzm1Sc=";
   };
 
   input2 = mkDerivation {
     shell = busybox;
     name = "build-remote-input-2";
-    buildCommand = "echo BAR > $out";
+    buildCommand = "echo hi; echo BAR > $out";
     requiredSystemFeatures = ["bar"];
     outputHash = "sha256-XArauVH91AVwP9hBBQNlkX9ccuPpSYx9o0zeIHb6e+Q=";
   };
@@ -34,6 +34,7 @@ let
     shell = busybox;
     name = "build-remote-input-3";
     buildCommand = ''
+      echo hi-input3
       read x < ${input2}
       echo $x BAZ > $out
     '';
@@ -46,6 +47,7 @@ in
   mkDerivation {
     shell = busybox;
     name = "build-remote";
+    passthru = { inherit input1 input2 input3; };
     buildCommand =
       ''
         read x < ${input1}

tests/build-hook.nix

@@ -9,27 +9,28 @@ let
       inherit system;
       builder = busybox;
       args = ["sh" "-e" args.builder or (builtins.toFile "builder-${args.name}.sh" "if [ -e .attrs.sh ]; then source .attrs.sh; fi; eval \"$buildCommand\"")];
-    } // removeAttrs args ["builder" "meta"])
-    // { meta = args.meta or {}; };
+    } // removeAttrs args ["builder" "meta" "passthru"])
+    // { meta = args.meta or {}; passthru = args.passthru or {}; };
 
   input1 = mkDerivation {
     shell = busybox;
     name = "build-remote-input-1";
-    buildCommand = "echo FOO > $out";
+    buildCommand = "echo hi-input1; echo FOO > $out";
     requiredSystemFeatures = ["foo"];
   };
 
   input2 = mkDerivation {
     shell = busybox;
     name = "build-remote-input-2";
-    buildCommand = "echo BAR > $out";
+    buildCommand = "echo hi; echo BAR > $out";
     requiredSystemFeatures = ["bar"];
   };
 
   input3 = mkDerivation {
     shell = busybox;
     name = "build-remote-input-3";
     buildCommand = ''
+      echo hi-input3
       read x < ${input2}
       echo $x BAZ > $out
     '';
@@ -41,6 +42,7 @@ in
   mkDerivation {
     shell = busybox;
     name = "build-remote";
+    passthru = { inherit input1 input2 input3; };
     buildCommand =
       ''
         read x < ${input1}

tests/build-remote.sh

@@ -54,6 +54,14 @@ nix path-info --store $TEST_ROOT/machine3 --all \
   | grep -v builder-build-remote-input-2.sh \
   | grep builder-build-remote-input-3.sh
 
+
+# Temporarily disabled because of https://github.com/NixOS/nix/issues/6209
+if [[ -z "$CONTENT_ADDRESSED" ]]; then
+  for i in input1 input3; do
+    nix log --store $TEST_ROOT/machine0 --file "$file" --arg busybox $busybox passthru."$i" | grep hi-$i
+  done
+fi
+
 # Behavior of keep-failed
 out="$(nix-build 2>&1 failing.nix \
   --builders "$(join_by '; ' "${builders[@]}")"  \