Merge pull request #9280 from R-VdP/rvdp/fix_remote_logging_phase_reporting

Include phase reporting in log file for ssh-ng builds

(cherry picked from commit b1e7d7cad625095656fff05ac4aedeb12135110a)
Change-Id: I4076669b0ba160412f7c628ca9113f9abbc8c303

src/libstore/build/derivation-goal.cc

@@ -1340,9 +1340,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")
+  '';
+}