stdenv: log hooks as they run (take II)

A second take at eb28e5e72ef9, which was reverted for the extra logging
during the internals of `nix-shell -p`. This commit does the same
logging, but to $NIX_LOG_FD instead, which is echoed during any normal
build, but not during the internals of `nix-shell -p`.

[1]: eb28e5e72ef912629ded3e265f7344ca21d115b9

1 files changed, 66 insertions, 4 deletions

diff --git a/pkgs/stdenv/generic/setup.sh b/pkgs/stdenv/generic/setup.sh
index 45c73d7709c66..780622c01883d 100644
--- a/pkgs/stdenv/generic/setup.sh
+++ b/pkgs/stdenv/generic/setup.sh
@@ -47,10 +47,67 @@ getAllOutputNames() {
     fi
 }
 
+if [[ -n "${NIX_LOG_FD:-}" ]]; then
+    # Logs arguments to $NIX_LOG_FD, if it exists, no-op if it does not.
+    nixLog() {
+        echo "$@" >&"$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.
+    _logHook() {
+        local hookKind="$1"
+        local hookExpr="$2"
+        shift 2
+
+        if declare -F "$hookExpr" > /dev/null 2>&1; then
+            nixLog "calling '$hookKind' function hook '$hookExpr'" "$@"
+        elif type -p "$hookExpr" > /dev/null; then
+            nixLog "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.
+            local exprToOutput
+            if (( "${NIX_DEBUG:-0}" >= 2 )); then
+                exprToOutput="$hookExpr"
+            else
+                # We have `r'\n'.join([line.lstrip() for lines in text.split('\n')])` at home.
+                local hookExprLine
+                while IFS= read -r hookExprLine; do
+                    # These lines often have indentation,
+                    # so let's remove leading whitespace.
+                    hookExprLine="${hookExprLine#"${hookExprLine%%[![:space:]]*}"}"
+                    # If this line wasn't entirely whitespace,
+                    # then add it to our output
+                    if [[ -n "$hookExprLine" ]]; then
+                        exprToOutput+="$hookExprLine\\n "
+                    fi
+                done <<< "$hookExpr"
+
+                # And then remove the final, unnecessary, \n
+                exprToOutput="${exprToOutput%%\\n }"
+            fi
+            nixLog "evaling '$hookKind' string hook '$exprToOutput'"
+        fi
+    }
+else
+    nixLog() {
+        # Stub.
+        # Note: because bash syntax, this colon is load bearing. Removing it
+        # will turn this function into a syntax error.
+        :
+    }
+
+    _logHook() {
+        # Load-bearing colon; same as above.
+        :
+    }
+fi
+
 ######################################################################
 # Hook handling.
 
-
 # Run all hooks with the specified name in the order in which they
 # were added, stopping if any fails (returns a non-zero exit
 # code). The hooks for <hookName> are the shell function or variable
@@ -64,6 +121,7 @@ runHook() {
     # Hack around old bash being bad and thinking empty arrays are
     # undefined.
     for hook in "_callImplicitHook 0 $hookName" ${!hooksSlice+"${!hooksSlice}"}; do
+        _logHook "$hookName" "$hook" "$@"
         _eval "$hook" "$@"
     done
 
@@ -81,6 +139,7 @@ runOneHook() {
     local hook ret=1
     # Hack around old bash like above
     for hook in "_callImplicitHook 1 $hookName" ${!hooksSlice+"${!hooksSlice}"}; do
+        _logHook "$hookName" "$hook" "$@"
         if _eval "$hook" "$@"; then
             ret=0
             break
@@ -100,10 +159,13 @@ _callImplicitHook() {
     local def="$1"
     local hookName="$2"
     if declare -F "$hookName" > /dev/null; then
+        nixLog "calling implicit '$hookName' function hook"
         "$hookName"
     elif type -p "$hookName" > /dev/null; then
+        nixLog "sourcing implicit '$hookName' script hook"
         source "$hookName"
     elif [ -n "${!hookName:-}" ]; then
+        nixLog "evaling implicit '$hookName' string hook"
         eval "${!hookName}"
     else
         return "$def"
@@ -644,6 +706,7 @@ activatePackage() {
     (( hostOffset <= targetOffset )) || exit 1
 
     if [ -f "$pkg" ]; then
+        nixLog "sourcing setup hook '$pkg'"
         source "$pkg"
     fi
 
@@ -667,6 +730,7 @@ activatePackage() {
     fi
 
     if [[ -f "$pkg/nix-support/setup-hook" ]]; then
+        nixLog "sourcing setup hook '$pkg/nix-support/setup-hook'"
         source "$pkg/nix-support/setup-hook"
     fi
 }
@@ -1558,9 +1622,7 @@ runPhase() {
     if [[ "$curPhase" = installCheckPhase && -z "${doInstallCheck:-}" ]]; then return; fi
     if [[ "$curPhase" = distPhase && -z "${doDist:-}" ]]; then return; fi
 
-    if [[ -n $NIX_LOG_FD ]]; then
-        echo "@nix { \"action\": \"setPhase\", \"phase\": \"$curPhase\" }" >&"$NIX_LOG_FD"
-    fi
+    nixLog "@nix { \"action\": \"setPhase\", \"phase\": \"$currPhase\" }"
 
     showPhaseHeader "$curPhase"
     dumpVars