diff --git a/lix/libutil/logging.cc b/lix/libutil/logging.cc index a0b4b3760..70523c230 100644 --- a/lix/libutil/logging.cc +++ b/lix/libutil/logging.cc @@ -279,6 +279,8 @@ Logger * makeJSONLogger(Logger & prevLogger) return new JSONLogger(prevLogger); } +MakeError(StructuredLogError, Error); + static Logger::Fields getFields(JSON & json) { Logger::Fields fields; @@ -287,7 +289,7 @@ static Logger::Fields getFields(JSON & json) fields.emplace_back(Logger::Field(f.get())); else if (f.type() == JSON::value_t::string) fields.emplace_back(Logger::Field(f.get())); - else throw Error("unsupported JSON type %d", (int) f.type()); + else throw StructuredLogError("unsupported log field type '%s'", f.type_name()); } return fields; } @@ -350,6 +352,11 @@ std::optional handleJSONLogMessage( "Unable to handle a JSON message from %s: %s", Uncolored(source), e.what() ); return std::nullopt; + } catch (StructuredLogError & e) { + printTaggedWarning( + "Unable to handle a JSON message from %s: %s", Uncolored(source), e.what() + ); + return std::nullopt; } } diff --git a/tests/functional/logging.sh b/tests/functional/logging.sh index 7dcfa0b57..1ccc21d0b 100644 --- a/tests/functional/logging.sh +++ b/tests/functional/logging.sh @@ -24,6 +24,3 @@ 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 deleted file mode 100644 index ddb8aa530..000000000 --- a/tests/functional/logging/unusual-logging.nix +++ /dev/null @@ -1,16 +0,0 @@ -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 - ''; -} diff --git a/tests/functional2/commands/test_build/assets/test_structured_build_logging/unusual-logging.nix b/tests/functional2/commands/test_build/assets/test_structured_build_logging/unusual-logging.nix new file mode 100644 index 000000000..841937a2b --- /dev/null +++ b/tests/functional2/commands/test_build/assets/test_structured_build_logging/unusual-logging.nix @@ -0,0 +1,30 @@ +let + inherit (import ./config.nix) mkDerivation; + strangeLog = + logCommands: + mkDerivation { + name = "unusual-logging"; + buildCommand = '' + { + ${logCommands} + } >&$NIX_LOG_FD + touch $out + ''; + }; + + makeBadLog = json: "echo '@nix ${json}'"; + makeBadLogs = logs: builtins.concatStringsSep "\n" (builtins.map makeBadLog logs); +in +rec { + normalInvalid = strangeLog (makeBadLogs normalInvalidLogs); + normalInvalidLogs = [ + "1" + "{}" + ''{"action": null}'' + ''{"action": 123}'' + "][" + ]; + + invalidFields = strangeLog (makeBadLog invalidFieldsLog); + invalidFieldsLog = ''{"action": "start", "fields": [1.5], "id": 2, "type": 1, "level": 1, "text": "abc"}''; +} diff --git a/tests/functional2/commands/test_build/test_structured_build_logging.py b/tests/functional2/commands/test_build/test_structured_build_logging.py new file mode 100644 index 000000000..b1fb26987 --- /dev/null +++ b/tests/functional2/commands/test_build/test_structured_build_logging.py @@ -0,0 +1,49 @@ +import logging +from testlib.fixtures.file_helper import CopyFile, with_files +from testlib.fixtures.nix import Nix +from testlib.utils import get_global_asset + + +_files = { + "config.nix": get_global_asset("config.nix"), + "unusual-logging.nix": CopyFile("assets/test_structured_build_logging/unusual-logging.nix"), +} + +_INVALID_LOG_WARNING = "message from the derivation builder: " + + +@with_files(_files) +def test_bad_logs(nix: Nix, logger: logging.Logger): + nix.settings.add_xp_feature("nix-command") + expected_errors = ( + nix.nix(["eval", "--json", "-f", "unusual-logging.nix", "normalInvalidLogs"]) + .run() + .ok() + .json() + ) + + res = nix.nix_build(["unusual-logging.nix", "-A", "normalInvalid"]) + errs = res.run().stderr_plain + logger.debug("err: %s", errs) + assert errs.count(_INVALID_LOG_WARNING) == len(expected_errors) + + # we expect that the error message contains the offending log line + for err in expected_errors: + assert err in errs + + +@with_files(_files) +def test_invalid_fields(nix: Nix, logger: logging.Logger): + nix.settings.add_xp_feature("nix-command") + expected_error = ( + nix.nix(["eval", "--json", "-f", "unusual-logging.nix", "invalidFieldsLog"]) + .run() + .ok() + .json() + ) + + res = nix.nix_build(["unusual-logging.nix", "-A", "invalidFields"]) + errs = res.run().stderr_plain + logger.debug("err: %s", errs) + assert _INVALID_LOG_WARNING in errs + assert expected_error in errs