Make @nix json structured build log parsing warn instead of fail #11921

roberth · 2024-11-20T10:31:03Z

Motivation

A build may log with @nix something without the intent to write Nix structured logs, resulting in an obscure error.
This makes it easy to understand and continues the build.

Example:

echo '@nix ]['

bad JSON log message from builder: [json.exception.parse_error.101] parse error at line 1, column 1: syntax error while parsing value - unexpected ']'; expected '[', '{', or a literal
@nix ][

Context

Cherry-picked from https://gerrit.lix.systems/c/lix/+/2057
Author @lheckemann

Priorities and Process

Add 👍 to pull requests you find important.

The Nix maintainer team uses a GitHub project board to schedule and track reviews.

Ericson2314 · 2024-11-20T20:13:46Z

src/libutil/logging.cc

+        return true;
+    } catch (nlohmann::json::exception &e) {
+        warn(
+            "warning: Unable to handle a JSON message from the builder: %s",


Don't like how this makes assumptions about where this function is being used.

Spot on. That also fixes a technically incorrect message, although it was probably never seen.
Now:

if (handleJSONLogMessage(s, worker.act, worker.hook->activities, "the build hook", true))

Ericson2314

+1 on the idea, just don't like the anti-modular way the warning is done.

roberth · 2024-11-21T15:09:34Z

Interestingly, the post-build-hook does not have @nix parsing logic, so that's what that's not in the diff.

Ericson2314

Great now!

Mic92 · 2024-11-24T10:21:06Z

@roberth CI fails.

nixos-discourse · 2024-11-27T20:00:13Z

This pull request has been mentioned on NixOS Discourse. There might be relevant details there:

https://discourse.nixos.org/t/2024-11-20-nix-team-meeting-minutes-196/56688/1

pwaller · 2024-12-06T15:56:27Z

Forgive me if this is off topic, but this might be of interest here: right now if I run nix develop -f . hello with nix 2.24.10 on nixos/nixpkgs@staging I get:

error: [json.exception.parse_error.101] parse error at line 38, column 445: syntax error while parsing value - invalid string: control character U+001E (RS) must be escaped to \u001E; last read: '" \n    local sep=\"$1\";\n    local name=\"$2\";\n    local type oldifs;\n    if type=$(declare -p \"$name\" 2> /dev/null); then\n        local -n nameref=\"$name\";\n        case \"${type#* }\" in \n            -A*)\n                echo \"concatStringsSep(): ERROR: trying to use concatStringsSep on an associative array.\" 1>&2;\n                return 1\n            ;;\n            -a*)\n                local IFS='<U+001E>'

With --verbose --debug the line that precedes the error is "reading environment file '/nix/store/bjazykbgvidfl19ma7gkm2jsxp0wkckn-hello-2.12.1-env'", and this seems to occur buliding any package I have tried.

@nix

Before this change, expressions like: with import <nixpkgs> {}; 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 e55cd3b)

…type errors

…warning correctly

wolfgangwalther · 2024-12-09T20:33:15Z

Forgive me if this is off topic, but this might be of interest here: right now if I run nix develop -f . hello with nix 2.24.10 on nixos/nixpkgs@staging I get:
error: [json.exception.parse_error.101] parse error at line 38, column 445: syntax error while parsing value - invalid string: control character U+001E (RS) must be escaped to \u001E; last read: '" \n    local sep=\"$1\";\n    local name=\"$2\";\n    local type oldifs;\n    if type=$(declare -p \"$name\" 2> /dev/null); then\n        local -n nameref=\"$name\";\n        case \"${type#* }\" in \n            -A*)\n                echo \"concatStringsSep(): ERROR: trying to use concatStringsSep on an associative array.\" 1>&2;\n                return 1\n            ;;\n            -a*)\n                local IFS='<U+001E>'
With --verbose --debug the line that precedes the error is "reading environment file '/nix/store/bjazykbgvidfl19ma7gkm2jsxp0wkckn-hello-2.12.1-env'", and this seems to occur buliding any package I have tried.

This has been fixed in nixpkgs in NixOS/nixpkgs#363672.

@nix

…1921 Make @nix json structured build log parsing warn instead of fail (backport #11921)

@nix

…1921 Make @nix json structured build log parsing warn instead of fail (backport #11921)

nixos-discourse · 2024-12-11T21:21:38Z

This pull request has been mentioned on NixOS Discourse. There might be relevant details there:

https://discourse.nixos.org/t/2024-12-09-nix-team-meeting-minutes-201/57280/1

@nix

Robert made these improvements on the PR that cherry-picked e55cd3b / https://gerrit.lix.systems/c/lix/+/2057 from Lix into CppNix: NixOS/nix#11921 Push log source description out of libutil and report build hook @nix warning correctly (cherry picked from commit 03d4bfd852dce9a050f984e887c887a43581796c) test: Move unusual-logging to run only in logging test case (cherry picked from commit 1421420e862434321c46511a3152016e443dd479) Remove redundant warning: prefix from structured build log warning (cherry picked from commit f3c722cab24f7a0de8c3573d25e91749f4f16234) Change-Id: I7da99046f2a41b3c58e62351119bc89bcc25a703

roberth added bug derivation-build The process of building an individual derivation (see also sandbox label) labels Nov 20, 2024

roberth requested a review from edolstra as a code owner November 20, 2024 10:31

github-actions bot added the with-tests Issues related to testing. PRs with tests have some priority label Nov 20, 2024

roberth added backport 2.24-maintenance Automatically creates a PR against the branch backport 2.25-maintenance Automatically creates a PR against the branch labels Nov 20, 2024

Ericson2314 reviewed Nov 20, 2024

View reviewed changes

roberth requested a review from Ericson2314 November 21, 2024 15:09

Ericson2314 approved these changes Nov 21, 2024

View reviewed changes

Ericson2314 mentioned this pull request Nov 24, 2024

libutil: handle json builder log messages with unexpected format #11939

Closed

roberth force-pushed the log-json-tolerant branch from 8179d9d to 2043cfa Compare November 24, 2024 22:52

Ericson2314 enabled auto-merge November 24, 2024 23:17

roberth and others added 7 commits December 9, 2024 15:59

tests/functional/dependencies.nix: Refactor, replace arcane let

e82ff51

tests/functional/dependencies.nix: Check that we tolerate syntax and …

1485937

…type errors

Push log source description out of libutil and report build hook @nix …

03d4bfd

…warning correctly

test: Move unusual-logging to run only in logging test case

1421420

Remove redundant warning: prefix from structured build log warning

f3c722c

tests: Make unusual logging test conditional on fixed daemon version

c783cd2

roberth force-pushed the log-json-tolerant branch from 2043cfa to c783cd2 Compare December 9, 2024 16:37

Mic92 mentioned this pull request Dec 9, 2024

stdenv: fix nix develop NixOS/nixpkgs#363672

Merged

13 tasks

philiptaron mentioned this pull request Dec 9, 2024

stdenv: support multi-char separators in concatStringsSep NixOS/nixpkgs#360466

Merged

13 tasks

Ericson2314 merged commit 747256c into master Dec 9, 2024
20 checks passed

Ericson2314 deleted the log-json-tolerant branch December 9, 2024 21:39

This was referenced Dec 9, 2024

Make @nix json structured build log parsing warn instead of fail (backport #11921) #12034

Merged

Make @nix json structured build log parsing warn instead of fail (backport #11921) #12035

Merged

Mic92 added a commit that referenced this pull request Dec 10, 2024

Merge pull request #12034 from NixOS/mergify/bp/2.24-maintenance/pr-1…

a4f978b

…1921 Make @nix json structured build log parsing warn instead of fail (backport #11921)

Mic92 added a commit that referenced this pull request Dec 10, 2024

Merge pull request #12035 from NixOS/mergify/bp/2.25-maintenance/pr-1…

fe3c94d

…1921 Make @nix json structured build log parsing warn instead of fail (backport #11921)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make @nix json structured build log parsing warn instead of fail #11921

Make @nix json structured build log parsing warn instead of fail #11921

roberth commented Nov 20, 2024

Ericson2314 Nov 20, 2024

roberth Nov 21, 2024

Ericson2314 left a comment

roberth commented Nov 21, 2024

Ericson2314 left a comment

Mic92 commented Nov 24, 2024

nixos-discourse commented Nov 27, 2024

pwaller commented Dec 6, 2024 •

edited

Loading

wolfgangwalther commented Dec 9, 2024

nixos-discourse commented Dec 11, 2024

Make @nix json structured build log parsing warn instead of fail #11921

Make @nix json structured build log parsing warn instead of fail #11921

Conversation

roberth commented Nov 20, 2024

Motivation

Context

Priorities and Process

Ericson2314 Nov 20, 2024

Choose a reason for hiding this comment

roberth Nov 21, 2024

Choose a reason for hiding this comment

Ericson2314 left a comment

Choose a reason for hiding this comment

roberth commented Nov 21, 2024

Ericson2314 left a comment

Choose a reason for hiding this comment

Mic92 commented Nov 24, 2024

nixos-discourse commented Nov 27, 2024

pwaller commented Dec 6, 2024 • edited Loading

wolfgangwalther commented Dec 9, 2024

nixos-discourse commented Dec 11, 2024

pwaller commented Dec 6, 2024 •

edited

Loading