From e82ff51726b33b95152c4c64dc870eab831936f9 Mon Sep 17 00:00:00 2001 From: Robert Hensing Date: Wed, 20 Nov 2024 11:05:55 +0100 Subject: [PATCH 1/7] tests/functional/dependencies.nix: Refactor, replace arcane let --- tests/functional/dependencies.nix | 25 ++++++++++++------------- 1 file changed, 12 insertions(+), 13 deletions(-) diff --git a/tests/functional/dependencies.nix b/tests/functional/dependencies.nix index be1a7ae9a6e..4ff29227fd3 100644 --- a/tests/functional/dependencies.nix +++ b/tests/functional/dependencies.nix @@ -1,7 +1,7 @@ { hashInvalidator ? "" }: with import ./config.nix; -let { +let input0 = mkDerivation { name = "dependencies-input-0"; @@ -33,16 +33,15 @@ let { outputHash = "1dq9p0hnm1y75q2x40fws5887bq1r840hzdxak0a9djbwvx0b16d"; }; - body = mkDerivation { - name = "dependencies-top"; - builder = ./dependencies.builder0.sh + "/FOOBAR/../."; - input1 = input1 + "/."; - input2 = "${input2}/."; - input1_drv = input1; - input2_drv = input2; - input0_drv = input0; - fod_input_drv = fod_input; - meta.description = "Random test package"; - }; - +in +mkDerivation { + name = "dependencies-top"; + builder = ./dependencies.builder0.sh + "/FOOBAR/../."; + input1 = input1 + "/."; + input2 = "${input2}/."; + input1_drv = input1; + input2_drv = input2; + input0_drv = input0; + fod_input_drv = fod_input; + meta.description = "Random test package"; } From ee03fd478e99d90eb02baefda6dee7eb9a3c347f Mon Sep 17 00:00:00 2001 From: Linus Heckemann Date: Fri, 11 Oct 2024 17:16:32 +0200 Subject: [PATCH 2/7] libutil: handle json builder log messages with unexpected format Before this change, expressions like: with import {}; runCommand "foo" {} '' echo '@nix {}' >&$NIX_LOG_FD '' would result in Lix crashing, because accessing nonexistent fields of a JSON object throws an exception. Rather than handling each field individually, we just catch JSON exceptions wholesale. Since these log messages are an unusual circumstance, log a warning when this happens. Fixes #544. Change-Id: Idc2d8acf6e37046b3ec212f42e29269163dca893 (cherry picked from commit e55cd3beea710db727fd966f265a1b715b7285f3) --- src/libutil/logging.cc | 60 +++++++++++++++++-------------- tests/functional/dependencies.nix | 13 +++++++ 2 files changed, 47 insertions(+), 26 deletions(-) diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc index 80c107ef538..0eceee6d4ce 100644 --- a/src/libutil/logging.cc +++ b/src/libutil/logging.cc @@ -295,37 +295,45 @@ 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)); - } + try { + 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 == "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 == "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 == "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); - } + else if (action == "msg") { + std::string msg = json["msg"]; + logger->log((Verbosity) json["level"], msg); + } - return true; + return true; + } catch (const nlohmann::json::exception &e) { + warn( + "warning: Unable to handle a JSON message from the builder: %s", + e.what() + ); + return false; + } } bool handleJSONLogMessage(const std::string & msg, diff --git a/tests/functional/dependencies.nix b/tests/functional/dependencies.nix index 4ff29227fd3..64d9d236009 100644 --- a/tests/functional/dependencies.nix +++ b/tests/functional/dependencies.nix @@ -33,6 +33,18 @@ let outputHash = "1dq9p0hnm1y75q2x40fws5887bq1r840hzdxak0a9djbwvx0b16d"; }; + unusual-logging = mkDerivation { + name = "unusual-logging"; + buildCommand = '' + { + echo "@nix 1" + echo "@nix {}" + echo '@nix {"action": null}' + } >&$NIX_LOG_FD + touch $out + ''; + }; + in mkDerivation { name = "dependencies-top"; @@ -42,6 +54,7 @@ mkDerivation { input1_drv = input1; input2_drv = input2; input0_drv = input0; + unusual_logging_drv = unusual-logging; fod_input_drv = fod_input; meta.description = "Random test package"; } From 1485937b897bc88cda0848b54b8ad9310230c47b Mon Sep 17 00:00:00 2001 From: Robert Hensing Date: Wed, 20 Nov 2024 11:16:39 +0100 Subject: [PATCH 3/7] tests/functional/dependencies.nix: Check that we tolerate syntax and type errors --- tests/functional/dependencies.nix | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/functional/dependencies.nix b/tests/functional/dependencies.nix index 64d9d236009..d177f5b6358 100644 --- a/tests/functional/dependencies.nix +++ b/tests/functional/dependencies.nix @@ -40,6 +40,8 @@ let echo "@nix 1" echo "@nix {}" echo '@nix {"action": null}' + echo '@nix {"action": 123}' + echo '@nix ][' } >&$NIX_LOG_FD touch $out ''; From 03d4bfd852dce9a050f984e887c887a43581796c Mon Sep 17 00:00:00 2001 From: Robert Hensing Date: Thu, 21 Nov 2024 16:03:21 +0100 Subject: [PATCH 4/7] Push log source description out of libutil and report build hook @nix warning correctly --- src/libstore/build/derivation-goal.cc | 8 ++++---- src/libutil/logging.cc | 17 ++++++++++------- src/libutil/logging.hh | 13 ++++++++++++- 3 files changed, 26 insertions(+), 12 deletions(-) diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc index bf1a25db1f0..2ff0ef92f2c 100644 --- a/src/libstore/build/derivation-goal.cc +++ b/src/libstore/build/derivation-goal.cc @@ -1161,7 +1161,7 @@ HookReply DerivationGoal::tryBuildHook() throw; } }(); - if (handleJSONLogMessage(s, worker.act, worker.hook->activities, true)) + if (handleJSONLogMessage(s, worker.act, worker.hook->activities, "the build hook", true)) ; else if (s.substr(0, 2) == "# ") { reply = s.substr(2); @@ -1346,9 +1346,9 @@ void DerivationGoal::handleChildOutput(Descriptor fd, std::string_view data) if (hook && fd == hook->fromHook.readSide.get()) { for (auto c : data) if (c == '\n') { - auto json = parseJSONMessage(currentHookLine); + auto json = parseJSONMessage(currentHookLine, "the derivation builder"); if (json) { - auto s = handleJSONLogMessage(*json, worker.act, hook->activities, true); + auto s = handleJSONLogMessage(*json, worker.act, hook->activities, "the derivation builder", true); // ensure that logs from a builder using `ssh-ng://` as protocol // are also available to `nix log`. if (s && !isWrittenToLog && logSink) { @@ -1390,7 +1390,7 @@ void DerivationGoal::handleEOF(Descriptor fd) void DerivationGoal::flushLine() { - if (handleJSONLogMessage(currentLogLine, *act, builderActivities, false)) + if (handleJSONLogMessage(currentLogLine, *act, builderActivities, "the derivation builder", false)) ; else { diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc index 0eceee6d4ce..4c706101651 100644 --- a/src/libutil/logging.cc +++ b/src/libutil/logging.cc @@ -280,20 +280,22 @@ static Logger::Fields getFields(nlohmann::json & json) return fields; } -std::optional parseJSONMessage(const std::string & msg) +std::optional parseJSONMessage(const std::string & msg, std::string_view source) { if (!hasPrefix(msg, "@nix ")) return std::nullopt; try { return nlohmann::json::parse(std::string(msg, 5)); } catch (std::exception & e) { - printError("bad JSON log message from builder: %s", e.what()); + printError("bad JSON log message from %s: %s", + Uncolored(source), + e.what()); } return std::nullopt; } bool handleJSONLogMessage(nlohmann::json & json, const Activity & act, std::map & activities, - bool trusted) + std::string_view source, bool trusted) { try { std::string action = json["action"]; @@ -329,7 +331,8 @@ bool handleJSONLogMessage(nlohmann::json & json, return true; } catch (const nlohmann::json::exception &e) { warn( - "warning: Unable to handle a JSON message from the builder: %s", + "warning: Unable to handle a JSON message from %s: %s", + Uncolored(source), e.what() ); return false; @@ -337,12 +340,12 @@ bool handleJSONLogMessage(nlohmann::json & json, } bool handleJSONLogMessage(const std::string & msg, - const Activity & act, std::map & activities, bool trusted) + const Activity & act, std::map & activities, std::string_view source, bool trusted) { - auto json = parseJSONMessage(msg); + auto json = parseJSONMessage(msg, source); if (!json) return false; - return handleJSONLogMessage(*json, act, activities, trusted); + return handleJSONLogMessage(*json, act, activities, source, trusted); } Activity::~Activity() diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh index 250f9209972..11e4033a59d 100644 --- a/src/libutil/logging.hh +++ b/src/libutil/logging.hh @@ -185,14 +185,25 @@ Logger * makeSimpleLogger(bool printBuildLogs = true); Logger * makeJSONLogger(Logger & prevLogger); -std::optional parseJSONMessage(const std::string & msg); +/** + * @param source A noun phrase describing the source of the message, e.g. "the builder". + */ +std::optional parseJSONMessage(const std::string & msg, std::string_view source); +/** + * @param source A noun phrase describing the source of the message, e.g. "the builder". + */ bool handleJSONLogMessage(nlohmann::json & json, const Activity & act, std::map & activities, + std::string_view source, bool trusted); +/** + * @param source A noun phrase describing the source of the message, e.g. "the builder". + */ bool handleJSONLogMessage(const std::string & msg, const Activity & act, std::map & activities, + std::string_view source, bool trusted); /** From 1421420e862434321c46511a3152016e443dd479 Mon Sep 17 00:00:00 2001 From: Robert Hensing Date: Mon, 9 Dec 2024 17:18:10 +0100 Subject: [PATCH 5/7] test: Move unusual-logging to run only in logging test case --- tests/functional/dependencies.nix | 15 --------------- tests/functional/logging.sh | 3 +++ tests/functional/logging/unusual-logging.nix | 16 ++++++++++++++++ 3 files changed, 19 insertions(+), 15 deletions(-) create mode 100644 tests/functional/logging/unusual-logging.nix diff --git a/tests/functional/dependencies.nix b/tests/functional/dependencies.nix index d177f5b6358..4ff29227fd3 100644 --- a/tests/functional/dependencies.nix +++ b/tests/functional/dependencies.nix @@ -33,20 +33,6 @@ let outputHash = "1dq9p0hnm1y75q2x40fws5887bq1r840hzdxak0a9djbwvx0b16d"; }; - unusual-logging = mkDerivation { - name = "unusual-logging"; - buildCommand = '' - { - echo "@nix 1" - echo "@nix {}" - echo '@nix {"action": null}' - echo '@nix {"action": 123}' - echo '@nix ][' - } >&$NIX_LOG_FD - touch $out - ''; - }; - in mkDerivation { name = "dependencies-top"; @@ -56,7 +42,6 @@ mkDerivation { input1_drv = input1; input2_drv = input2; input0_drv = input0; - unusual_logging_drv = unusual-logging; fod_input_drv = fod_input; meta.description = "Random test package"; } diff --git a/tests/functional/logging.sh b/tests/functional/logging.sh index c026ac9c211..bbc1bac96e3 100755 --- a/tests/functional/logging.sh +++ b/tests/functional/logging.sh @@ -28,3 +28,6 @@ outp="$(nix-build -E \ test -d "$outp" nix log "$outp" + +# Build works despite ill-formed structured build log entries. +expectStderr 0 nix build -f ./logging/unusual-logging.nix --no-link | grepQuiet 'warning: Unable to handle a JSON message from the derivation builder:' diff --git a/tests/functional/logging/unusual-logging.nix b/tests/functional/logging/unusual-logging.nix new file mode 100644 index 00000000000..ddb8aa53010 --- /dev/null +++ b/tests/functional/logging/unusual-logging.nix @@ -0,0 +1,16 @@ +let + inherit (import ../config.nix) mkDerivation; +in +mkDerivation { + name = "unusual-logging"; + buildCommand = '' + { + echo "@nix 1" + echo "@nix {}" + echo '@nix {"action": null}' + echo '@nix {"action": 123}' + echo '@nix ][' + } >&$NIX_LOG_FD + touch $out + ''; +} From f3c722cab24f7a0de8c3573d25e91749f4f16234 Mon Sep 17 00:00:00 2001 From: Robert Hensing Date: Mon, 9 Dec 2024 17:20:27 +0100 Subject: [PATCH 6/7] Remove redundant warning: prefix from structured build log warning --- src/libutil/logging.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc index 4c706101651..a5add5565df 100644 --- a/src/libutil/logging.cc +++ b/src/libutil/logging.cc @@ -331,7 +331,7 @@ bool handleJSONLogMessage(nlohmann::json & json, return true; } catch (const nlohmann::json::exception &e) { warn( - "warning: Unable to handle a JSON message from %s: %s", + "Unable to handle a JSON message from %s: %s", Uncolored(source), e.what() ); From c783cd22ac1c693871979c4248d7f7b2b7f6bacd Mon Sep 17 00:00:00 2001 From: Robert Hensing Date: Mon, 9 Dec 2024 17:29:45 +0100 Subject: [PATCH 7/7] tests: Make unusual logging test conditional on fixed daemon version --- tests/functional/logging.sh | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/functional/logging.sh b/tests/functional/logging.sh index bbc1bac96e3..ddb1913adf2 100755 --- a/tests/functional/logging.sh +++ b/tests/functional/logging.sh @@ -29,5 +29,7 @@ test -d "$outp" nix log "$outp" -# Build works despite ill-formed structured build log entries. -expectStderr 0 nix build -f ./logging/unusual-logging.nix --no-link | grepQuiet 'warning: Unable to handle a JSON message from the derivation builder:' +if isDaemonNewer "2.26"; then + # Build works despite ill-formed structured build log entries. + expectStderr 0 nix build -f ./logging/unusual-logging.nix --no-link | grepQuiet 'warning: Unable to handle a JSON message from the derivation builder:' +fi