From bbb9f2f1c98768a1ff623fbe730c71d4871646b5 Mon Sep 17 00:00:00 2001 From: Philip Taron Date: Fri, 2 Aug 2024 14:07:03 -0700 Subject: [PATCH 1/5] stdenv: set the phase in showPhaseHeader --- pkgs/stdenv/generic/setup.sh | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/pkgs/stdenv/generic/setup.sh b/pkgs/stdenv/generic/setup.sh index cc69434dc8c9..fc1f6b7d7478 100644 --- a/pkgs/stdenv/generic/setup.sh +++ b/pkgs/stdenv/generic/setup.sh @@ -1597,6 +1597,13 @@ distPhase() { showPhaseHeader() { local phase="$1" echo "Running phase: $phase" + + # The Nix structured logger allows derivations to update the phase as they're building, + # which shows up in the terminal UI. See `handleJSONLogMessage` in the Nix source. + if [[ -z ${NIX_LOG_FD-} ]]; then + return + fi + printf "@nix { \"action\": \"setPhase\", \"phase\": \"%s\" }\n" "$phase" >&"$NIX_LOG_FD" } @@ -1629,8 +1636,6 @@ runPhase() { if [[ "$curPhase" = installCheckPhase && -z "${doInstallCheck:-}" ]]; then return; fi if [[ "$curPhase" = distPhase && -z "${doDist:-}" ]]; then return; fi - nixLog "@nix { \"action\": \"setPhase\", \"phase\": \"$curPhase\" }" - showPhaseHeader "$curPhase" dumpVars From 624463391d94d0fc505f50f26f02d95e3a72c60c Mon Sep 17 00:00:00 2001 From: Philip Taron Date: Fri, 2 Aug 2024 14:27:08 -0700 Subject: [PATCH 2/5] stdenv: introduce specific logging functions --- pkgs/stdenv/generic/setup.sh | 66 +++++++++++++++++++++++++++++++++++- 1 file changed, 65 insertions(+), 1 deletion(-) diff --git a/pkgs/stdenv/generic/setup.sh b/pkgs/stdenv/generic/setup.sh index fc1f6b7d7478..a93f3c25ef7e 100644 --- a/pkgs/stdenv/generic/setup.sh +++ b/pkgs/stdenv/generic/setup.sh @@ -12,7 +12,15 @@ fi shopt -s inherit_errexit -if (( "${NIX_DEBUG:-0}" >= 6 )); then +# $NIX_DEBUG must be a documented integer level, if set, so we can use it safely as an integer. +# See the `Verbosity` enum in the Nix source for these levels. +if ! [[ -z ${NIX_DEBUG-} || $NIX_DEBUG == [0-7] ]]; then + printf 'The `NIX_DEBUG` environment variable has an unexpected value: %s\n' "${NIX_DEBUG}" + echo "It can only be unset or an integer between 0 and 7." + exit 1 +fi + +if [[ ${NIX_DEBUG:-0} -ge 6 ]]; then set -x fi @@ -55,6 +63,62 @@ nixLog() { echo "$@" >&"$NIX_LOG_FD" } +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlError` in the Nix source. +nixErrorLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 0 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlWarn` in the Nix source. +nixWarnLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 1 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlNotice` in the Nix source. +nixNoticeLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 2 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlInfo` in the Nix source. +nixInfoLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 3 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlTalkative` in the Nix source. +nixTalkativeLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 4 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlChatty` in the Nix source. +nixChattyLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 5 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlDebug` in the Nix source. +nixDebugLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 6 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + +# All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. +# Corresponds to `Verbosity::lvlVomit` in the Nix source. +nixVomitLog() { + if [[ -z ${NIX_LOG_FD-} ]] || [[ ${NIX_DEBUG:-0} -lt 7 ]]; then return; fi + printf "%s\n" "$*" >&"$NIX_LOG_FD" +} + # Log a hook, to be run before the hook is actually called. # logging for "implicit" hooks -- the ones specified directly # in derivation's arguments -- is done in _callImplicitHook instead. From 465dbd2ddf6197f006411a9ff632d9ed2e9c5e38 Mon Sep 17 00:00:00 2001 From: Philip Taron Date: Fri, 2 Aug 2024 14:41:27 -0700 Subject: [PATCH 3/5] stdenv: log hooks at nixTalkativeLog level MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Nix filters out messages with level ≥ 4 by default as of this commit. --- pkgs/stdenv/generic/setup.sh | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/pkgs/stdenv/generic/setup.sh b/pkgs/stdenv/generic/setup.sh index a93f3c25ef7e..c248d0b3f958 100644 --- a/pkgs/stdenv/generic/setup.sh +++ b/pkgs/stdenv/generic/setup.sh @@ -123,7 +123,7 @@ nixVomitLog() { # logging for "implicit" hooks -- the ones specified directly # in derivation's arguments -- is done in _callImplicitHook instead. _logHook() { - # Fast path in case nixLog is no-op. + # Fast path in case nixTalkativeLog is no-op. if [[ -z ${NIX_LOG_FD-} ]]; then return fi @@ -133,14 +133,14 @@ _logHook() { shift 2 if declare -F "$hookExpr" > /dev/null 2>&1; then - nixLog "calling '$hookKind' function hook '$hookExpr'" "$@" + nixTalkativeLog "calling '$hookKind' function hook '$hookExpr'" "$@" elif type -p "$hookExpr" > /dev/null; then - nixLog "sourcing '$hookKind' script hook '$hookExpr'" + nixTalkativeLog "sourcing '$hookKind' script hook '$hookExpr'" elif [[ "$hookExpr" != "_callImplicitHook"* ]]; then # Here we have a string hook to eval. - # Join lines onto one with literal \n characters unless NIX_DEBUG >= 2. + # Join lines onto one with literal \n characters unless NIX_DEBUG >= 5. local exprToOutput - if (( "${NIX_DEBUG:-0}" >= 2 )); then + if [[ ${NIX_DEBUG:-0} -ge 5 ]]; then exprToOutput="$hookExpr" else # We have `r'\n'.join([line.lstrip() for lines in text.split('\n')])` at home. @@ -159,7 +159,7 @@ _logHook() { # And then remove the final, unnecessary, \n exprToOutput="${exprToOutput%%\\n }" fi - nixLog "evaling '$hookKind' string hook '$exprToOutput'" + nixTalkativeLog "evaling '$hookKind' string hook '$exprToOutput'" fi } @@ -217,13 +217,13 @@ _callImplicitHook() { local def="$1" local hookName="$2" if declare -F "$hookName" > /dev/null; then - nixLog "calling implicit '$hookName' function hook" + nixTalkativeLog "calling implicit '$hookName' function hook" "$hookName" elif type -p "$hookName" > /dev/null; then - nixLog "sourcing implicit '$hookName' script hook" + nixTalkativeLog "sourcing implicit '$hookName' script hook" source "$hookName" elif [ -n "${!hookName:-}" ]; then - nixLog "evaling implicit '$hookName' string hook" + nixTalkativeLog "evaling implicit '$hookName' string hook" eval "${!hookName}" else return "$def" @@ -769,7 +769,7 @@ activatePackage() { (( hostOffset <= targetOffset )) || exit 1 if [ -f "$pkg" ]; then - nixLog "sourcing setup hook '$pkg'" + nixTalkativeLog "sourcing setup hook '$pkg'" source "$pkg" fi @@ -793,7 +793,7 @@ activatePackage() { fi if [[ -f "$pkg/nix-support/setup-hook" ]]; then - nixLog "sourcing setup hook '$pkg/nix-support/setup-hook'" + nixTalkativeLog "sourcing setup hook '$pkg/nix-support/setup-hook'" source "$pkg/nix-support/setup-hook" fi } From e844424e4f9b8107ca0055c8a67f8a003ee2b2a1 Mon Sep 17 00:00:00 2001 From: Philip Taron Date: Fri, 2 Aug 2024 14:50:40 -0700 Subject: [PATCH 4/5] stdenv: replace other $NIX_DEBUG log statements --- pkgs/stdenv/generic/setup.sh | 31 ++++++++----------------------- 1 file changed, 8 insertions(+), 23 deletions(-) diff --git a/pkgs/stdenv/generic/setup.sh b/pkgs/stdenv/generic/setup.sh index c248d0b3f958..afdfc4eec8de 100644 --- a/pkgs/stdenv/generic/setup.sh +++ b/pkgs/stdenv/generic/setup.sh @@ -55,14 +55,6 @@ getAllOutputNames() { fi } -# Logs arguments to $NIX_LOG_FD, if it exists, no-op if it does not. -nixLog() { - if [[ -z ${NIX_LOG_FD-} ]]; then - return - fi - echo "$@" >&"$NIX_LOG_FD" -} - # All provided arguments are joined with a space then directed to $NIX_LOG_FD, if it's set. # Corresponds to `Verbosity::lvlError` in the Nix source. nixErrorLog() { @@ -539,10 +531,7 @@ done unset i -if (( "${NIX_DEBUG:-0}" >= 1 )); then - echo "initial path: $PATH" -fi - +nixWarnLog "initial path: $PATH" # Check that the pre-hook initialised SHELL. if [ -z "${SHELL:-}" ]; then echo "SHELL not set"; exit 1; fi @@ -905,11 +894,10 @@ fi PATH="${_PATH-}${_PATH:+${PATH:+:}}$PATH" HOST_PATH="${_HOST_PATH-}${_HOST_PATH:+${HOST_PATH:+:}}$HOST_PATH" export XDG_DATA_DIRS="${_XDG_DATA_DIRS-}${_XDG_DATA_DIRS:+${XDG_DATA_DIRS:+:}}${XDG_DATA_DIRS-}" -if (( "${NIX_DEBUG:-0}" >= 1 )); then - echo "final path: $PATH" - echo "final host path: $HOST_PATH" - echo "final data dirs: $XDG_DATA_DIRS" -fi + +nixWarnLog "final path: $PATH" +nixWarnLog "final host path: $HOST_PATH" +nixWarnLog "final data dirs: $XDG_DATA_DIRS" unset _PATH unset _HOST_PATH @@ -1058,14 +1046,11 @@ substituteInPlace() { } _allFlags() { - # export some local variables for the awk below - # so some substitutions such as name don't have to be in the env attrset - # when __structuredAttrs is enabled + # Export some local variables for the `awk` below so some substitutions (such as name) + # don't have to be in the env attrset when `__structuredAttrs` is enabled. export system pname name version while IFS='' read -r varName; do - if (( "${NIX_DEBUG:-0}" >= 1 )); then - printf "@%s@ -> %q\n" "${varName}" "${!varName}" >&2 - fi + nixWarnLog "@${varName}@" "->" "${!varName}" args+=("--subst-var" "$varName") done < <(awk 'BEGIN { for (v in ENVIRON) if (v ~ /^[a-z][a-zA-Z0-9_]*$/) print v }') } From d8fbb162190086dbab5fb69adab3ae187f138672 Mon Sep 17 00:00:00 2001 From: Philip Taron Date: Mon, 5 Aug 2024 16:18:14 -0700 Subject: [PATCH 5/5] stdenv: change the logging in _allFlags to talkative --- pkgs/stdenv/generic/setup.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkgs/stdenv/generic/setup.sh b/pkgs/stdenv/generic/setup.sh index afdfc4eec8de..fc748aa12a66 100644 --- a/pkgs/stdenv/generic/setup.sh +++ b/pkgs/stdenv/generic/setup.sh @@ -1050,7 +1050,7 @@ _allFlags() { # don't have to be in the env attrset when `__structuredAttrs` is enabled. export system pname name version while IFS='' read -r varName; do - nixWarnLog "@${varName}@" "->" "${!varName}" + nixTalkativeLog "@${varName}@ -> ${!varName}" args+=("--subst-var" "$varName") done < <(awk 'BEGIN { for (v in ENVIRON) if (v ~ /^[a-z][a-zA-Z0-9_]*$/) print v }') }