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

Include phase reporting in log file for ssh-ng builds
This commit is contained in:
Théophane Hufschmitt 2023-11-17 14:37:09 +01:00 committed by GitHub
commit b1e7d7cad6
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
3 changed files with 130 additions and 3 deletions

View file

@ -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) {
auto f = (*json)["fields"];
(*logSink)((f.size() > 0 ? f.at(0).get<std::string>() : "") + "\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<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();

View file

@ -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;

View file

@ -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")
'';
}