From 706f0df55b4aaf7d0441227338bd4bec7121fe67 Mon Sep 17 00:00:00 2001 From: eldritch horrors Date: Thu, 7 Mar 2024 02:31:59 +0100 Subject: [PATCH] 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 | 23 +++++- tests/nixos/default.nix | 2 + tests/nixos/remote-builds-ssh-ng.nix | 108 ++++++++++++++++++++++++++ 3 files changed, 130 insertions(+), 3 deletions(-) create mode 100644 tests/nixos/remote-builds-ssh-ng.nix diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc index 01643605f..dadaccbcf 100644 --- a/src/libstore/build/derivation-goal.cc +++ b/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) { - auto f = (*json)["fields"]; - (*logSink)((f.size() > 0 ? f.at(0).get() : "") + "\n"); + if (s && !isWrittenToLog && logSink) { + const auto type = (*json)["type"]; + const auto fields = (*json)["fields"]; + if (type == resBuildLogLine) { + (*logSink)((fields.size() > 0 ? fields[0].get() : "") + "\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(); diff --git a/tests/nixos/default.nix b/tests/nixos/default.nix index cbb5dea00..4c1cf785c 100644 --- a/tests/nixos/default.nix +++ b/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; diff --git a/tests/nixos/remote-builds-ssh-ng.nix b/tests/nixos/remote-builds-ssh-ng.nix new file mode 100644 index 000000000..b59dde9bf --- /dev/null +++ b/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") + ''; +}