stdenv: log hooks as they run (take II)

A second take at eb28e5e, 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]: eb28e5e

pkgs/stdenv/generic/setup.sh

@@ -47,9 +47,59 @@ getAllOutputNames() {
     fi
 }
 
+# Logs arguments to $NIX_LOG_FD, if it exists, no-op if it does not.
+if [[ -n "${NIX_LOG_FD:-}" ]]; then
+    nixLog() {
+        echo "$@" >&"$NIX_LOG_FD"
+    }
+else
+    nixLog() {
+        # Stub.
+        # Note: because bash syntax, this colon is load bearing. Removing it
+        # will turn this function into a syntax error.
+        :
+    }
+fi
+
 ######################################################################
 # Hook handling.
 
+# 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
+            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
+}
 
 # Run all hooks with the specified name in the order in which they
 # were added, stopping if any fails (returns a non-zero exit
@@ -64,6 +114,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 +132,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 +152,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 +699,7 @@ activatePackage() {
     (( hostOffset <= targetOffset )) || exit 1
 
     if [ -f "$pkg" ]; then
+        nixLog "sourcing setup hook '$pkg'"
         source "$pkg"
     fi
 
@@ -667,6 +723,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 +1615,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