fix: structured build logs: bad field types no longer fail builds

Caught by edef's harness. I rewrote the structured build log tests in
f2 and added a test for this one.

Before: it failed the build altogether:
```
building '/tmp/jade/pytest-of-jade/pytest-77/test_invalid_fields_files0_0/nix/store/skhjs5zs082nqiakj69qz32gyywz0v1a-unusual-loggi
ng.drv'...
error: unsupported JSON type 7
```

Now the output is as expected:

```
warning: Unable to handle a JSON message from the derivation builder: error: unsupported log field type number
@nix {"action": "start", "fields": [1.5], "id": 2, "type": 1, "level": 1, "text": "abc"}
```

Change-Id: Idbd28c5a4d4cf15f27207f83b730e7946a6a6964

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<uint64_t>()));
         else if (f.type() == JSON::value_t::string)
             fields.emplace_back(Logger::Field(f.get<std::string>()));
-        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<Logger::BufferState> 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;
     }
 }
 

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:'

tests/functional/logging/unusual-logging.nix

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

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

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