From 7a04839ea53986a0175bf085e7d061ab8a32d59b Mon Sep 17 00:00:00 2001 From: Maximilian Bosch Date: Mon, 31 Jan 2022 22:05:28 +0100 Subject: [PATCH 1/7] ssh-ng: also store build logs to make them accessible by `nix log` Right now when building a derivation remotely via $ nix build -j0 -f . hello -L --builders 'ssh://builder' it's possible later to read through the entire build-log by running `nix log -f . hello`. This isn't possible however when using `ssh-ng` rather than `ssh`. The reason for that is that there are two different ways to transfer logs in Nix through e.g. an SSH tunnel (that are used by `ssh`/`ssh-ng` respectively): * `ssh://` receives its logs from the fd pointing to `builderOut`. This is directly passed to the "log-sink" (and to the logger on each `\n`), hence `nix log` works here. * `ssh-ng://` however expects JSON-like messages (i.e. `@nix {log data in here}`) and passes it directly to the logger without doing anything with the `logSink`. However it's certainly possible to extract log-lines from this format as these have their own message-type in the JSON payload (i.e. `resBuildLogLine`). This is basically what I changed in this patch: if the code-path for `builderOut` is not reached and a `logSink` is initialized, the message was successfully processed by the JSON logger (i.e. it's in the expected format) and the line is of the expected type (i.e. `resBuildLogLine`), the line will be written to the log-sink as well. Closes #5079 --- src/libstore/build/derivation-goal.cc | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc index 95da1841d..ef1135601 100644 --- a/src/libstore/build/derivation-goal.cc +++ b/src/libstore/build/derivation-goal.cc @@ -1175,10 +1175,10 @@ bool DerivationGoal::isReadDesc(int fd) return fd == hook->builderOut.readSide.get(); } - void DerivationGoal::handleChildOutput(int fd, std::string_view data) { - if (isReadDesc(fd)) + auto isWrittenToLog = isReadDesc(fd); + if (isWrittenToLog) { logSize += data.size(); if (settings.maxLogSize && logSize > settings.maxLogSize) { @@ -1207,7 +1207,14 @@ 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 s = handleJSONLogMessage(currentHookLine, worker.act, hook->activities, true); + if (s && !isWrittenToLog && logSink) { + auto json = nlohmann::json::parse(std::string(currentHookLine, 5)); + if (json["type"] == resBuildLogLine) { + auto f = json["fields"]; + (*logSink)((f.size() > 0 ? f.at(0).get() : "") + "\n"); + } + } currentHookLine.clear(); } else currentHookLine += c; From cd92ea588504db697103d3ff56166fe61e6da131 Mon Sep 17 00:00:00 2001 From: Maximilian Bosch Date: Sat, 19 Feb 2022 22:34:50 +0100 Subject: [PATCH 2/7] libstore/derivation-goal: avoid double-parsing of JSON messages To avoid that JSON messages are parsed twice in case of remote builds with `ssh-ng://`, I split up the original `handleJSONLogMessage` into three parts: * `parseJSONMessage(const std::string&)` checks if it's a message in the form of `@nix {...}` and tries to parse it (and prints an error if the parsing fails). * `handleJSONLogMessage(nlohmann::json&, ...)` reads the fields from the message and passes them to the logger. * `handleJSONLogMessage(const std::string&, ...)` behaves as before, but uses the two functions mentioned above as implementation. In case of `ssh-ng://`-logs the first two methods are invoked manually. --- src/libstore/build/derivation-goal.cc | 14 +++-- src/libutil/logging.cc | 84 +++++++++++++++------------ src/libutil/logging.hh | 8 +++ 3 files changed, 64 insertions(+), 42 deletions(-) diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc index ef1135601..c49be5e79 100644 --- a/src/libstore/build/derivation-goal.cc +++ b/src/libstore/build/derivation-goal.cc @@ -1207,12 +1207,14 @@ void DerivationGoal::handleChildOutput(int fd, std::string_view data) if (hook && fd == hook->fromHook.readSide.get()) { for (auto c : data) if (c == '\n') { - auto s = handleJSONLogMessage(currentHookLine, worker.act, hook->activities, true); - if (s && !isWrittenToLog && logSink) { - auto json = nlohmann::json::parse(std::string(currentHookLine, 5)); - if (json["type"] == resBuildLogLine) { - auto f = json["fields"]; - (*logSink)((f.size() > 0 ? f.at(0).get() : "") + "\n"); + auto json = parseJSONMessage(currentHookLine); + if (json) { + auto s = handleJSONLogMessage(*json, worker.act, hook->activities, true); + if (s && !isWrittenToLog && logSink) { + if ((*json)["type"] == resBuildLogLine) { + auto f = (*json)["fields"]; + (*logSink)((f.size() > 0 ? f.at(0).get() : "") + "\n"); + } } } currentHookLine.clear(); diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc index 74ee2f063..cb2b15b41 100644 --- a/src/libutil/logging.cc +++ b/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 & activities, bool trusted) +std::optional 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)); - } - - else if (action == "stop") - activities.erase((ActivityId) json["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 == "setPhase") { - std::string phase = json["phase"]; - act.result(resSetPhase, phase); - } - - else if (action == "msg") { - std::string msg = json["msg"]; - logger->log((Verbosity) json["level"], msg); - } - + 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; +} + +bool handleJSONLogMessage(nlohmann::json & json, + const Activity & act, std::map & 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 == "stop") + activities.erase((ActivityId) json["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 == "setPhase") { + std::string phase = json["phase"]; + act.result(resSetPhase, phase); + } + + 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 & activities, bool trusted) +{ + auto json = parseJSONMessage(msg); + if (!json) return false; + + return handleJSONLogMessage(*json, act, activities, trusted); +} + Activity::~Activity() { try { diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh index bd28036ae..9ab2091c7 100644 --- a/src/libutil/logging.hh +++ b/src/libutil/logging.hh @@ -4,6 +4,8 @@ #include "error.hh" #include "config.hh" +#include + namespace nix { typedef enum { @@ -166,6 +168,12 @@ Logger * makeSimpleLogger(bool printBuildLogs = true); Logger * makeJSONLogger(Logger & prevLogger); +std::optional parseJSONMessage(const std::string & msg); + +bool handleJSONLogMessage(nlohmann::json & json, + const Activity & act, std::map & activities, + bool trusted); + bool handleJSONLogMessage(const std::string & msg, const Activity & act, std::map & activities, bool trusted); From 287642f132d8141269bd7c23b0bc7c1ee512b171 Mon Sep 17 00:00:00 2001 From: Maximilian Bosch Date: Sun, 20 Feb 2022 15:56:22 +0100 Subject: [PATCH 3/7] tests: implement test for `nix log` with `ssh-ng://` builds A few notes: * The `echo hi` is needed to make sure that a file that can be read by `nix log` is properly created (i.e. some output is needed). This is known and to be fixed in #6051. * We explicitly ignore the floating-CA case here: the `$out` of `input3` depends on `$out` of `input2`. This means that there are actually two derivations - I assume that this is because at eval time (i.e. `nix-instantiate -A`) the hash of `input2` isn't known yet and the other .drv is created as soon as `input2` was built. This is another issue on its own, so we ignore the case here explicitly. --- tests/build-hook-ca-fixed.nix | 10 ++++++---- tests/build-hook.nix | 10 ++++++---- tests/build-remote.sh | 8 ++++++++ 3 files changed, 20 insertions(+), 8 deletions(-) diff --git a/tests/build-hook-ca-fixed.nix b/tests/build-hook-ca-fixed.nix index ec7171ac9..899b610a8 100644 --- a/tests/build-hook-ca-fixed.nix +++ b/tests/build-hook-ca-fixed.nix @@ -11,13 +11,13 @@ 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; echo FOO > $out"; requiredSystemFeatures = ["foo"]; outputHash = "sha256-FePFYIlMuycIXPZbWi7LGEiMmZSX9FMbaQenWBzm1Sc="; }; @@ -25,7 +25,7 @@ let 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 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} diff --git a/tests/build-hook.nix b/tests/build-hook.nix index eb16676f0..3c83e0475 100644 --- a/tests/build-hook.nix +++ b/tests/build-hook.nix @@ -9,20 +9,20 @@ 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; 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"]; }; @@ -30,6 +30,7 @@ let shell = busybox; name = "build-remote-input-3"; buildCommand = '' + echo hi 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} diff --git a/tests/build-remote.sh b/tests/build-remote.sh index 806c6d261..4ecc788a3 100644 --- a/tests/build-remote.sh +++ b/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 + +if [[ -z "$CONTENT_ADDRESSED" ]]; then + for i in input1 input3; do + drv="$(nix-instantiate $file -A passthru.$i --store $TEST_ROOT/machine0 --arg busybox $busybox)" + nix log --store $TEST_ROOT/machine0 "$drv" + done +fi + # Behavior of keep-failed out="$(nix-build 2>&1 failing.nix \ --builders "$(join_by '; ' "${builders[@]}")" \ From 102cb390864f8a142ad6730d3456784e2778a493 Mon Sep 17 00:00:00 2001 From: Maximilian Bosch Date: Sun, 20 Feb 2022 16:02:44 +0100 Subject: [PATCH 4/7] libstore/build: add a few explanatory comments; simplify --- src/libstore/build/derivation-goal.cc | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc index c49be5e79..ae250ffaf 100644 --- a/src/libstore/build/derivation-goal.cc +++ b/src/libstore/build/derivation-goal.cc @@ -1177,6 +1177,7 @@ bool DerivationGoal::isReadDesc(int fd) void DerivationGoal::handleChildOutput(int fd, std::string_view data) { + // local & `ssh://`-builds are dealt with here. auto isWrittenToLog = isReadDesc(fd); if (isWrittenToLog) { @@ -1210,11 +1211,11 @@ void DerivationGoal::handleChildOutput(int fd, std::string_view data) auto json = parseJSONMessage(currentHookLine); if (json) { auto s = handleJSONLogMessage(*json, worker.act, hook->activities, true); - if (s && !isWrittenToLog && logSink) { - if ((*json)["type"] == resBuildLogLine) { - auto f = (*json)["fields"]; - (*logSink)((f.size() > 0 ? f.at(0).get() : "") + "\n"); - } + // 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"); } } currentHookLine.clear(); From 6a8f1b548fc85af7e065feee93920839ec94fa40 Mon Sep 17 00:00:00 2001 From: Maximilian Bosch Date: Mon, 28 Feb 2022 16:05:21 +0100 Subject: [PATCH 5/7] logging.hh: json.hpp -> json_fwd.hpp --- src/libutil/logging.hh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh index 9ab2091c7..6f81b92de 100644 --- a/src/libutil/logging.hh +++ b/src/libutil/logging.hh @@ -4,7 +4,7 @@ #include "error.hh" #include "config.hh" -#include +#include namespace nix { From 697d1dac0164001a10ab990a382ad83f2e7628d4 Mon Sep 17 00:00:00 2001 From: Maximilian Bosch Date: Fri, 4 Mar 2022 16:58:27 +0100 Subject: [PATCH 6/7] tests: grep for string in nix log for remote-builds --- tests/build-hook-ca-fixed.nix | 4 ++-- tests/build-hook.nix | 4 ++-- tests/build-remote.sh | 3 +-- 3 files changed, 5 insertions(+), 6 deletions(-) diff --git a/tests/build-hook-ca-fixed.nix b/tests/build-hook-ca-fixed.nix index 899b610a8..4cb9e85d1 100644 --- a/tests/build-hook-ca-fixed.nix +++ b/tests/build-hook-ca-fixed.nix @@ -17,7 +17,7 @@ let input1 = mkDerivation { shell = busybox; name = "build-remote-input-1"; - buildCommand = "echo hi; echo FOO > $out"; + buildCommand = "echo hi-input1; echo FOO > $out"; requiredSystemFeatures = ["foo"]; outputHash = "sha256-FePFYIlMuycIXPZbWi7LGEiMmZSX9FMbaQenWBzm1Sc="; }; @@ -34,7 +34,7 @@ let shell = busybox; name = "build-remote-input-3"; buildCommand = '' - echo hi + echo hi-input3 read x < ${input2} echo $x BAZ > $out ''; diff --git a/tests/build-hook.nix b/tests/build-hook.nix index 3c83e0475..643334caa 100644 --- a/tests/build-hook.nix +++ b/tests/build-hook.nix @@ -15,7 +15,7 @@ let input1 = mkDerivation { shell = busybox; name = "build-remote-input-1"; - buildCommand = "echo hi; echo FOO > $out"; + buildCommand = "echo hi-input1; echo FOO > $out"; requiredSystemFeatures = ["foo"]; }; @@ -30,7 +30,7 @@ let shell = busybox; name = "build-remote-input-3"; buildCommand = '' - echo hi + echo hi-input3 read x < ${input2} echo $x BAZ > $out ''; diff --git a/tests/build-remote.sh b/tests/build-remote.sh index 4ecc788a3..a2c3b9ce7 100644 --- a/tests/build-remote.sh +++ b/tests/build-remote.sh @@ -57,8 +57,7 @@ nix path-info --store $TEST_ROOT/machine3 --all \ if [[ -z "$CONTENT_ADDRESSED" ]]; then for i in input1 input3; do - drv="$(nix-instantiate $file -A passthru.$i --store $TEST_ROOT/machine0 --arg busybox $busybox)" - nix log --store $TEST_ROOT/machine0 "$drv" + nix log --store $TEST_ROOT/machine0 --file "$file" --arg busybox $busybox passthru."$i" | grep hi-$i done fi From 860016bcbf1ea91289ebc5d495eccfe43f22ac62 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Th=C3=A9ophane=20Hufschmitt?= <7226587+thufschmitt@users.noreply.github.com> Date: Mon, 7 Mar 2022 09:15:34 +0100 Subject: [PATCH 7/7] Explain why the log tests are disabled for CA derivations --- tests/build-remote.sh | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/build-remote.sh b/tests/build-remote.sh index a2c3b9ce7..094366872 100644 --- a/tests/build-remote.sh +++ b/tests/build-remote.sh @@ -55,6 +55,7 @@ nix path-info --store $TEST_ROOT/machine3 --all \ | 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