Skip to content

Commit

Permalink
Merge pull request #11921 from NixOS/log-json-tolerant
Browse files Browse the repository at this point in the history
Make @nix json structured build log parsing warn instead of fail
  • Loading branch information
Ericson2314 authored Dec 9, 2024
2 parents b6250dc + c783cd2 commit 747256c
Show file tree
Hide file tree
Showing 6 changed files with 92 additions and 50 deletions.
8 changes: 4 additions & 4 deletions src/libstore/build/derivation-goal.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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 {
Expand Down
75 changes: 43 additions & 32 deletions src/libutil/logging.cc
Original file line number Diff line number Diff line change
Expand Up @@ -280,61 +280,72 @@ static Logger::Fields getFields(nlohmann::json & json)
return fields;
}

std::optional<nlohmann::json> parseJSONMessage(const std::string & msg)
std::optional<nlohmann::json> 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<ActivityId, Activity> & activities,
bool trusted)
std::string_view source, 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(
"Unable to handle a JSON message from %s: %s",
Uncolored(source),
e.what()
);
return false;
}
}

bool handleJSONLogMessage(const std::string & msg,
const Activity & act, std::map<ActivityId, Activity> & activities, bool trusted)
const Activity & act, std::map<ActivityId, Activity> & 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()
Expand Down
13 changes: 12 additions & 1 deletion src/libutil/logging.hh
Original file line number Diff line number Diff line change
Expand Up @@ -185,14 +185,25 @@ Logger * makeSimpleLogger(bool printBuildLogs = true);

Logger * makeJSONLogger(Logger & prevLogger);

std::optional<nlohmann::json> parseJSONMessage(const std::string & msg);
/**
* @param source A noun phrase describing the source of the message, e.g. "the builder".
*/
std::optional<nlohmann::json> 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<ActivityId, Activity> & 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<ActivityId, Activity> & activities,
std::string_view source,
bool trusted);

/**
Expand Down
25 changes: 12 additions & 13 deletions tests/functional/dependencies.nix
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
{ hashInvalidator ? "" }:
with import ./config.nix;

let {
let

input0 = mkDerivation {
name = "dependencies-input-0";
Expand Down Expand Up @@ -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";
}
5 changes: 5 additions & 0 deletions tests/functional/logging.sh
Original file line number Diff line number Diff line change
Expand Up @@ -28,3 +28,8 @@ outp="$(nix-build -E \
test -d "$outp"

nix log "$outp"

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
16 changes: 16 additions & 0 deletions tests/functional/logging/unusual-logging.nix
Original file line number Diff line number Diff line change
@@ -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
'';
}

0 comments on commit 747256c

Please sign in to comment.