libstore/ssh-ng: Fix phase reporting in log files.

When doing local builds, we get phase reporting lines in the log file,
they look like '@nix {"action":"setPhase","phase":"unpackPhase"}'.
With the ssh-ng protocol, we do have access to these messages, but since we
are only including messages of type resBuildLogLine in the logs, the phase
information does not end up in the log file.

The phase reporting could probably be improved altoghether (it looks like it
is kind of accidental that these JSON messages for phase reporting show up
but others don't, just because they are actually emitted by nixpkgs' stdenv),
but as a first step I propose to make ssh-ng behave in the same way as local builds do.

src/libstore/build/derivation-goal.cc

@@ -1317,9 +1317,26 @@ void DerivationGoal::handleChildOutput(int fd, std::string_view data)
                     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) {
+                    if (s && !isWrittenToLog && logSink) {
-                        auto f = (*json)["fields"];
+                        const auto type = (*json)["type"];
-                        (*logSink)((f.size() > 0 ? f.at(0).get<std::string>() : "") + "\n");
+                        const auto fields = (*json)["fields"];
+                        if (type == resBuildLogLine) {
+                            (*logSink)((fields.size() > 0 ? fields[0].get<std::string>() : "") + "\n");
+                        } else if (type == resSetPhase && ! fields.is_null()) {
+                            const auto phase = fields[0];
+                            if (! phase.is_null()) {
+                                // nixpkgs' stdenv produces lines in the log to signal
+                                // phase changes.
+                                // We want to get the same lines in case of remote builds.
+                                // The format is:
+                                //   @nix { "action": "setPhase", "phase": "$curPhase" }
+                                const auto logLine = nlohmann::json::object({
+                                    {"action", "setPhase"},
+                                    {"phase", phase}
+                                });
+                                (*logSink)("@nix " + logLine.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace) + "\n");
+                            }
+                        }
                     }
                 }
                 currentHookLine.clear();

tests/nixos/default.nix

@@ -21,6 +21,8 @@ in
 
   remoteBuilds = runNixOSTestFor "x86_64-linux" ./remote-builds.nix;
 
+  remoteBuildsSshNg = runNixOSTestFor "x86_64-linux" ./remote-builds-ssh-ng.nix;
+
   nix-copy-closure = runNixOSTestFor "x86_64-linux" ./nix-copy-closure.nix;
 
   nix-copy = runNixOSTestFor "x86_64-linux" ./nix-copy.nix;

tests/nixos/remote-builds-ssh-ng.nix

@@ -0,0 +1,108 @@
+{ config, lib, hostPkgs, ... }:
+
+let
+  pkgs = config.nodes.client.nixpkgs.pkgs;
+
+  # Trivial Nix expression to build remotely.
+  expr = config: nr: pkgs.writeText "expr.nix"
+    ''
+      let utils = builtins.storePath ${config.system.build.extraUtils}; in
+      derivation {
+        name = "hello-${toString nr}";
+        system = "i686-linux";
+        PATH = "''${utils}/bin";
+        builder = "''${utils}/bin/sh";
+        args = [ "-c" "${
+          lib.concatStringsSep "; " [
+            ''if [[ -n $NIX_LOG_FD ]]''
+            ''then echo '@nix {\"action\":\"setPhase\",\"phase\":\"buildPhase\"}' >&''$NIX_LOG_FD''
+            "fi"
+            "echo Hello"
+            "mkdir $out"
+            "cat /proc/sys/kernel/hostname > $out/host"
+          ]
+        }" ];
+        outputs = [ "out" ];
+      }
+    '';
+in
+
+{
+  name = "remote-builds-ssh-ng";
+
+  nodes =
+    { builder =
+      { config, pkgs, ... }:
+      { services.openssh.enable = true;
+        virtualisation.writableStore = true;
+        nix.settings.sandbox = true;
+        nix.settings.substituters = lib.mkForce [ ];
+      };
+
+      client =
+        { config, lib, pkgs, ... }:
+        { nix.settings.max-jobs = 0; # force remote building
+          nix.distributedBuilds = true;
+          nix.buildMachines =
+            [ { hostName = "builder";
+                sshUser = "root";
+                sshKey = "/root/.ssh/id_ed25519";
+                system = "i686-linux";
+                maxJobs = 1;
+                protocol = "ssh-ng";
+              }
+            ];
+          virtualisation.writableStore = true;
+          virtualisation.additionalPaths = [ config.system.build.extraUtils ];
+          nix.settings.substituters = lib.mkForce [ ];
+          programs.ssh.extraConfig = "ConnectTimeout 30";
+        };
+    };
+
+  testScript = { nodes }: ''
+    # fmt: off
+    import subprocess
+
+    start_all()
+
+    # Create an SSH key on the client.
+    subprocess.run([
+      "${hostPkgs.openssh}/bin/ssh-keygen", "-t", "ed25519", "-f", "key", "-N", ""
+    ], capture_output=True, check=True)
+    client.succeed("mkdir -p -m 700 /root/.ssh")
+    client.copy_from_host("key", "/root/.ssh/id_ed25519")
+    client.succeed("chmod 600 /root/.ssh/id_ed25519")
+
+    # Install the SSH key on the builder.
+    client.wait_for_unit("network.target")
+    builder.succeed("mkdir -p -m 700 /root/.ssh")
+    builder.copy_from_host("key.pub", "/root/.ssh/authorized_keys")
+    builder.wait_for_unit("sshd")
+    client.succeed(f"ssh -o StrictHostKeyChecking=no {builder.name} 'echo hello world'")
+
+    # Perform a build
+    out = client.succeed("nix-build ${expr nodes.client.config 1} 2> build-output")
+
+    # Verify that the build was done on the builder
+    builder.succeed(f"test -e {out.strip()}")
+
+    # Print the build log, prefix the log lines to avoid nix intercepting lines starting with @nix
+    buildOutput = client.succeed("sed -e 's/^/build-output:/' build-output")
+    print(buildOutput)
+
+    # Make sure that we get the expected build output
+    client.succeed("grep -qF Hello build-output")
+
+    # We don't want phase reporting in the build output
+    client.fail("grep -qF '@nix' build-output")
+
+    # Get the log file
+    client.succeed(f"nix-store --read-log {out.strip()} > log-output")
+    # Prefix the log lines to avoid nix intercepting lines starting with @nix
+    logOutput = client.succeed("sed -e 's/^/log-file:/' log-output")
+    print(logOutput)
+
+    # Check that we get phase reporting in the log file
+    client.succeed("grep -q '@nix {\"action\":\"setPhase\",\"phase\":\"buildPhase\"}' log-output")
+  '';
+}