stdenv: refactor nix logging functions#370742
Conversation
nix-owners
bot
requested review from
Artturin,
Ericson2314,
RossComputerGuy,
emilazy and
reckenrode
github-actions
bot
added
10.rebuild-darwin: 5001+
RossComputerGuy
left a comment
RossComputerGuy
left a comment
There was a problem hiding this comment.
LGTM, I like how we can see where the calls are coming from with this.
wegank
added
12.approvals: 1
philiptaron
left a comment
philiptaron
left a comment
There was a problem hiding this comment.
A few comments here and there, but nothing blocking.
| callerName="${hookName:?}" | ||
| fi | ||
|
|
||
| # Use the function name of the caller's caller, since we should only every be invoked by nix*Log functions. |
There was a problem hiding this comment.
This comment is sort of duplicated with the above; I'd remove it. The thing that should replace it is a note that we could be using structured logging here.
I can't find any user-facing documentation of structured logging; the function that does it is here.
There was a problem hiding this comment.
I had looked into using that previously, but correctly escaping JSON within Bash is very difficult. When I ignored that and tried to use simple text, I noticed it messed with the formatting of the output when --print-build-logs was passed to Nix. After that, I sort of shelved it. I'll add additional context to the PR description -- @emilazy had good ideas about how a better logging solution would function and I want to make a note of them, but it would require changes on the Nix side as well.
There was a problem hiding this comment.
I definitely agree with all of that. It's bleeding edge at the moment, no doubt.
|
|
||
| # All provided arguments are joined with a space, then prefixed by the name of the function which invoked `nixLog` (or | ||
| # the hook name if the caller was an implicit hook), then directed to $NIX_LOG_FD, if it's set. | ||
| nixLog() { |
There was a problem hiding this comment.
nixLog used to accept other arguments. I deleted it (and there was no fallout, shockingly.)
I'm in favor of it returning.
There was a problem hiding this comment.
I didn't see other arguments accepted by nixLog prior to that PR; as it is implemented currently it accepts an arbitrary number of arguments but passes them as a single string to printf. I also wanted to avoid configurability and argument parsing.
|
I'm going to merge this now, thank you for the feedback @philiptaron! |
4 participants
Package maintainers frequently include
echocommands in their phase expressions to provide breadcrumbs for debugging or information for troubleshooting. To try to standardize the logging format and avoid the need to remember to pipe the output fromechoto stderr orNIX_LOG_FD, we have the log-level family of functions (nix*Log) and an unconditional log function,nixLog.The
nix*Logfunction family only prints toNIX_LOG_FDwhen the severity of the log message is at least the value ofNIX_DEBUG. This should be the preferred logger.The
nixLogfunction logs unconditionally and is meant to be used to provide information about the status of some process or phase (e.g., log messages delimiting a series ofsubstituteInPlacecalls, or to notify about the progress of a setup hook). It should never be used by trivial builders or writers (see #328229).These functions both make use of Bash's
FUNCNAMEshell variable to prefix the logged message with the caller (or the phase name, if the caller is an implicit hook), which is extremely useful when debugging failing phases.I've been using this change to great success in an external repo containing a rewrite of our CUDA packaging: it is implemented here https://github.com/ConnorBaker/cuda-packages/tree/main/upstreamable-packages/nixLogWithLevelAndFunctionNameHook and an example of its use is here https://github.com/ConnorBaker/cuda-packages/blob/358e4a6a73f11042f4454e81918039e62ddfb261/cuda-packages/common/setupCudaHook/setup-cuda-hook.sh. I'm submitting it here because I believe it can help remove ad-hoc
echostatements while also enriching our build logs.Here's a snippet of the output I see when I build
nccl:Details
Prior work
Sourcing setup hook *default hook*spam in writers/trivial builders #328229Future work
Ideally, we would have better integration with the Nix CLI such that using structured logging is enough for the CLI to filter messages.
Rebuilding derivations just to see logs with a higher level of verbosity is frustrating because it slows down development and introduces additional steps to get more visibility into failures. Instead, the Nix build log should be at full verbosity so that information is always available and the CLI should filter the output before display.
Things done
nix.conf? (See Nix manual)sandbox = relaxedsandbox = truenix-shell -p nixpkgs-review --run "nixpkgs-review rev HEAD". Note: all changes have to be committed, also see nixpkgs-review usage./result/bin/)Add a 👍 reaction to pull requests you find important.