{nix,lix,stdenv}: log hook information only if NIX_DEBUG >= 1; provide means to set it

[philiptaron]

Motivation for changes

• Sourcing setup hook *default hook* spam in writers/trivial builders #328229

Ever since Qyriad's excellent PRs (#290081, #310387) to make hooks more visible in the nixpkgs stdenv landed, we've been caught between two goals:

1. Being able to understand what a hook does.
2. Being overwhelmed by the amount of information to skip over.

In the issue linked above, there's a real tension: we want to understand what's happening with a derivation without changing its hash -- but we also don't want to see this debugging information every time.

Description of changes

These commits piggyback on the existing NIX_DEBUG environment variable to turn on and turn off the hook logging. So, if NIX_DEBUG is 1 or greater, the hook logging is turned on.

There was, however, no documented way of setting the NIX_DEBUG variable in the Nix build environment.

This patch adds an off-by-default option to the Nix and Lix derivations which allows building Nix such that the NIX_DEBUG variable is set in the Nix build environment.

Yes, this is a total hack, and has no upstream warranty either express or implied. For such a "deep into the sauce" sort of debugging that needs this variable set, I feel that's OK.

I'll extract the somewhat arcane grep | sed thing into an actual patch if people are aligned on this direction.

Things done

• Built on platform(s)
  • x86_64-linux
  • aarch64-linux
  • x86_64-darwin
  • aarch64-darwin
• For non-Linux: Is sandboxing enabled in nix.conf? (See Nix manual)
  • sandbox = relaxed
  • sandbox = true
• Tested, as applicable:
  • NixOS test(s) (look inside nixos/tests)
  • and/or package tests
  • or, for functions and "core" functionality, tests in lib/tests or pkgs/test
  • made sure NixOS tests are linked to the relevant packages
• Tested compilation of all packages that depend on this change using nix-shell -p nixpkgs-review --run "nixpkgs-review rev HEAD". Note: all changes have to be committed, also see nixpkgs-review usage
• Tested basic functionality of all binary files (usually in ./result/bin/)
• 24.11 Release Notes (or backporting 23.11 and 24.05 Release notes)
  • (Package updates) Added a release notes entry if the change is major or breaking
  • (Module updates) Added a release notes entry if the change is significant
  • (Module addition) Added a release notes entry if adding a new NixOS module
• Fits CONTRIBUTING.md.

Fixes #328229.

[Atemu]

The idea gets an ACK from me but this snippet must be refactored; it is unreadable.

Ideally, we'd have this as a build-time (or even runtime) feature in Lix.

[philiptaron]

I'm going to collect more feedback before investing the work to do that, especially if the idea itself gets mondo pushback from others. Having it work with upstream support definitely is "the right way", for sure.

[AndersonTorres]

I would say that the complain of Atemu is nonsense, given that grep and xargs are usually unreadable.

However, to me it looks like you are editing C source code, and in those cases I prefer to use parametric patches.

[Mindavi]

I'm sorry to say, but I think this brings in an impurity that may cause different build results with the same hash, if for some reason a package uses this environment variable to make decisions.

[Atemu]

That's indeed correct, it being an impurity is the whole point. Same drv, different log output.

If your derivation used NIX_DEBUG to decide on anything other than whether to display additional info during the build and therefore causes the output to change, I'd consider that to be a bug in your derivation though.

[flokli]

Isn't this whole structured logging functionality in Nix the right candidate for this? Shouldn't this allow us to send these debug messages to there, and it'd be up to nix to filter this dynamically?

[tie]

What if we use msg action with level for @nix (i.e. #328229 (comment)) and then work on supporting multiple log levels for --print-build-logs in Nix? E.g. implement some function nixLogWithLevel that maps human-readable log level names to integers for @nix and use that instead of nixLogDebug.

This looks like a reasonable compromise to me because it appears to avoid log spam during builds (that I think was the main concern in #328229) but we’d retain these messages in nix log.

$ cat msglevel.nix
let
  pkgs = import ./. { };
in
pkgs.runCommand "nix-msg-level" { } ''
  nixLog "@nix { \"action\": \"msg\", \"msg\": \"hello world\", \"level\": 7 }"
  touch -- "$out"
''
$ nix build --rebuild --print-build-logs --file msglevel.nix
$ nix log ./result
@nix { "action": "msg", "msg": "hello world", "level": 7 }

(I’ve intentionally omitted sourcing setup hook logs above for brevity)

Nix seems to filter out messages with level ≥ 4 by default.

[philiptaron]

Today, my plan is to split this into three PRs:

1. Move the hook logging as it currently exists to only trigger if NIX_DEBUG is set, and I'll take @emilazy's feedback that the "sourcing" logs ought to go to NIX_DEBUG >= 2. I expect this PR to be accepted and merged, and it will close Sourcing setup hook *default hook* spam in writers/trivial builders #328229.

   • stdenv: only log hooks if $NIX_DEBUG >= 4 #331560

2. Provide the hack to build Nix & Lix with NIX_DEBUG in the derivation build environment. I expect this PR to be rejected, and anticipate closing it after that rejection. I can live with an overlay for Nix & Lix in my own configuration, and there's enough traces of the discussion to point people at how to do it even if the PR is rejected.

   • {nix,lix}: add withNixDebug overrideable #331794

3. Make a speculative stdenv patch that uses structured logging, in particular the log level mechanism. I expect this PR to generate commentary and not be merged in the end, but it may serve as a place to discuss how the stdenv ought to interweave with Nix logging.

Related PRs and projects I've found from feedback on Matrix and elsewhere:

1. Add an option to print the logs in a machine-readable format nix#3073 (in particular fe9d2f9)
2. ssh-ng: also store build logs to make them accessible by nix log nix#6029
3. Nix OpenTelemetry sender plugin (and more generally Collect build time statistics nix#1710)
4. Add builtins.debug nix#4914 and especially this comment from @roberth.
5. Semantically meaningful ways to communicate our intent nix#749 in the Nix evaluator, closed last week.

Please let me know if there are other links and projects of note.

[philiptaron]

Closed because #331560 has landed. I'll commence work on this:

Make a speculative stdenv patch that uses structured logging, in particular the log level mechanism. I expect this PR to generate commentary and not be merged in the end, but it may serve as a place to discuss how the stdenv ought to interweave with Nix logging.