stdenv: log build hooks as they run #290081

Qyriad · 2024-02-20T01:08:16Z

Description of changes

Hooks are vital to Nixpkgs, and are often the "magic" to make things Just Work, but they're also extremely opaque. Adding something like undmg to a derivation's nativeBuildInputs adds a hook to the unpackPhase to automatically extract DMG sources — this is fantastic, but a beginner would have no way of knowing that adding something as a build input could have such a major effect (undmg gets only a single passing mention in the Nixpkgs manual), and even to Nixpkgs veterans it's far from obvious what the final array of hooks for a build might be, or what order they even run in (a source of confusion if one causes an error!).

This PR changes stdenv's setup.sh to log hooks to stdout as they run, as it does currently with phases. Setup hook files are logged just before they're sourced, and individual build hooks like patchShebangsAuto are also logged just before they're run.

With this PR, now anyone building with --print-build-logs will have transparency into one of the most important aspects of Nixpkgs, to aid heavily in both debugging and learning.

For example, here what it now looks like when building Curlie:

sourcing setup hook '/nix/store/33jvc2jsv20lsx8dp0pwf0rr7xhwwpq9-patchelf-0.15.0/nix-support/setuphook'
sourcing setup hook '/nix/store/qmavq4i2rh012ggwb5fxlvp3pzhxmbkl-update-autotools-gnu-config-scripts-hook/nix-support/setuphook'
sourcing setup hook '/nix/store/h9lc1dpi14z7is86ffhl3ld569138595-audit-tmpdir.sh'
sourcing setup hook '/nix/store/m54bmrhj6fqz8nds5zcj97w9s9bckc9v-compress-man-pages.sh'
sourcing setup hook '/nix/store/wgrbkkaldkrlrni33ccvm3b6vbxzb656-make-symlinks-relative.sh'
sourcing setup hook '/nix/store/5yzw0vhkyszf2d179m0qfkgxmp5wjjx4-move-docs.sh'
sourcing setup hook '/nix/store/fyaryjvghbkpfnsyw97hb3lyb37s1pd6-move-lib64.sh'
sourcing setup hook '/nix/store/kd4xwxjpjxi71jkm6ka0np72if9rm3y0-move-sbin.sh'
sourcing setup hook '/nix/store/pag6l61paj1dc9sv15l7bm5c17xn5kyk-move-systemd-user-units.sh'
sourcing setup hook '/nix/store/jivxp510zxakaaic7qkrb7v1dd2rdbw9-multiple-outputs.sh'
sourcing setup hook '/nix/store/wzdsbnv2ba3nj91aql8jjdddfmkkdh7h-patch-shebangs.sh'
sourcing setup hook '/nix/store/cickvswrvann041nqxb0rxilc46svw1n-prune-libtool-files.sh'
sourcing setup hook '/nix/store/xyff06pkhki3qy1ls77w10s0v79c9il0-reproducible-builds.sh'
sourcing setup hook '/nix/store/ngg1cv31c8c7bcm2n8ww4g06nq7s4zhm-set-source-date-epoch-to-latest.sh'
sourcing setup hook '/nix/store/wmknncrif06fqxa16hpdldhixk95nds0-strip.sh'
sourcing setup hook '/nix/store/w0x01w0vcdzvaj90axjxq6w2p290cp5m-gcc-wrapper-13.2.0/nix-support/setuphook'
sourcing setup hook '/nix/store/1byi00pspg4j6jpvaj4xn2mfkyh28g9g-binutils-wrapper-2.40/nix-support/setuphook'
@nix { "action": "setPhase", "phase": "unpackPhase" }
Running phase: unpackPhase
unpacking source archive /nix/store/1mmyk26f86cg3cvs9djg0l4cf95hwl7q-source
calling 'unpackCmd' function hook '_defaultUnpack' /nix/store/1mmyk26f86cg3cvs9djg0l4cf95hwl7q-source
source root is source
calling 'postUnpack' function hook '_updateSourceDateEpochFromSourceRoot'
@nix { "action": "setPhase", "phase": "patchPhase" }
Running phase: patchPhase
applying patch /nix/store/2q6i5q3jin7d357dm53hdkancj5wzpaq-bump-golang-x-sys.patch
patching file go.mod
patching file go.sum
@nix { "action": "setPhase", "phase": "updateAutotoolsGnuConfigScriptsPhase" }
Running phase: updateAutotoolsGnuConfigScriptsPhase
@nix { "action": "setPhase", "phase": "configurePhase" }
Running phase: configurePhase
calling 'preConfigure' function hook '_multioutConfig'
@nix { "action": "setPhase", "phase": "buildPhase" }
Running phase: buildPhase
Building subPackage .
Building subPackage ./args
Building subPackage ./formatter
@nix { "action": "setPhase", "phase": "checkPhase" }
Running phase: checkPhase
ok  	github.com/rs/curlie/args	0.001s
@nix { "action": "setPhase", "phase": "installPhase" }
Running phase: installPhase
@nix { "action": "setPhase", "phase": "fixupPhase" }
Running phase: fixupPhase
calling 'preFixup' function hook '_moveToShare'
calling 'preFixup' function hook '_multioutDocs'
calling 'preFixup' function hook '_multioutDevs'
evaling 'fixupOutput' string hook 'if [ -z "${dontPatchELF-}" ]; then patchELF "$prefix"; fi'
shrinking RPATHs of ELF executables and libraries in /nix/store/crnvz72hxrp3cc0wrfcdaivyymqiy55q-curlie-1.7.2
shrinking /nix/store/crnvz72hxrp3cc0wrfcdaivyymqiy55q-curlie-1.7.2/bin/curlie
patchelf: cannot find section '.dynamic'. The input file is most likely statically linked
evaling 'fixupOutput' string hook 'if [[ -z "${noAuditTmpdir-}" && -e "$prefix" ]]; then auditTmpdir "$prefix"; fi'
checking for references to /build/ in /nix/store/crnvz72hxrp3cc0wrfcdaivyymqiy55q-curlie-1.7.2...
patchelf: cannot find section '.dynamic'. The input file is most likely statically linked
evaling 'fixupOutput' string hook 'if [ -z "${dontGzipMan-}" ]; then compressManPages "$prefix"; fi'
calling 'fixupOutput' function hook '_moveLib64'
calling 'fixupOutput' function hook '_moveSbin'
calling 'fixupOutput' function hook '_moveSystemdUserUnits'
calling 'fixupOutput' function hook 'patchShebangsAuto'
patching script interpreter paths in /nix/store/crnvz72hxrp3cc0wrfcdaivyymqiy55q-curlie-1.7.2
calling 'fixupOutput' function hook '_pruneLibtoolFiles'
calling 'fixupOutput' function hook '_doStrip'
stripping (with command strip and flags -S -p) in  /nix/store/crnvz72hxrp3cc0wrfcdaivyymqiy55q-curlie-1.7.2/bin
calling 'postFixup' function hook '_makeSymlinksRelativeInAllOutputs'
calling 'postFixup' function hook '_multioutPropagateDev'

There are more example output diffs at https://github.com/Qyriad/nixpkgs/compare/before/diag/log-hooks...Qyriad:nixpkgs:after/diag/log-hooks?diff=split&w=.

Things done

Add a 👍 reaction to pull requests you find important.

IreneKnapp · 2024-02-24T02:31:22Z

This is an excellent idea, I like it a lot.

pkgs/stdenv/generic/setup.sh

Addresses the following review comments: - https://github.com/NixOS/nixpkgs/pull/290081/files/eb28e5e72ef912629ded3e265f7344ca21d115b9#r1501466125 - https://github.com/NixOS/nixpkgs/pull/290081/files/eb28e5e72ef912629ded3e265f7344ca21d115b9#r1501466232 This will be squashed into the previous commit pending review.

Qyriad · 2024-02-26T05:21:38Z

Thanks @fogti! Those are now fixed

philiptaron

I like how this makes the Nix build process more discoverable. I've learned a lot about Nix from reading logs, and this turbo-charges that process.

I've got a couple questions about the most complicated piece of this review, the "${NIX_DEBUG:-0}" < 2 section. Dropping that complexity would be ideal, in my view, if it didn't come with bad tradeoffs.

pkgs/stdenv/generic/setup.sh

philiptaron · 2024-02-27T01:05:56Z

pkgs/stdenv/generic/setup.sh

+            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 }"


This is cute, but what's the damage just showing the log-viewing user what the hook value is directly? How many of these are there?

Not many. I only know of one, which is autoPatchelfHook. I ran rg -U -t sh 'hook.?\+?=\(.\n' to try to find other examples but I couldn't find any, though I'm not confidant that regex is all-inclusive. By far most hooks are either functions, or single-line if [[ -z "${dontDoHookThing-}" ]]; then doHookThing; fi. I am fine with splatting out potential multiline hooks, and autoPatchelfHook could easily be changed to do its multiline logic in its hook function instead of inline.

philiptaron · 2024-02-27T01:07:59Z

pkgs/stdenv/generic/setup.sh

        source "$hookName"
    elif [ -n "${!hookName:-}" ]; then
+        echo "evaling implicit '$hookName' string hook"


For instance, here you don't do the trick with "${NIX_DEBUG:-0}" >= 2 and just splat it out.

Actually this part doesn't splat out the hook string — since implicit hooks are for specifying "one-off" hooks right in a derivation, they're going to be specified by the derivation being built itself. Those often are multiline, but since they're also by far the most obvious hooks, I went with just logging the name. So something like

preConfigure = '' some foo commands '';

Gets logged as evaling implicit 'preConfigure' hook without printing the text itself. If you have something better I'm absolutely all ears 🙂

That's definitely good enough. Thanks for the example.

I wonder (and this isn't for this review) whether "implicit" is the right name for this concept, and whether "immediate" or "derivation-supplied" might be a better name. In fact, from the perspective of the derivation or package author, they might be thought of as "explicit" hooks as opposed to the "implicit" ones that come from elsewhere. An irony if so.

A lot of my time spent debugging this ended up actually amounting to figuring out what implicit hooks are and where they come from and why there's a separate, special mechanism for them in stdenv 😅

So I completely agree; a rename of the concept would be very helpful. "Immediate" is decent, but further bikeshedding can be at a later date

Addresses the following review comment: NixOS#290081 (comment) This will be squashed into the previous commit pending review. Co-authored-by: Philip Taron <philip.taron@gmail.com>

philiptaron · 2024-02-28T00:32:45Z

OK, I made a version of this PR (philiptaron@e7e7675) that I could grep through the produced build logs and see what it looked like.

After building my entire machine derivation:

$ fd bz2$ /nix/var/log/nix/drvs/ | xargs bzcat | rg https://github.com/NixOS/nixpkgs/pull/290081 | sort | uniq -c
     27 https://github.com/NixOS/nixpkgs/pull/290081: evaling 'fixupOutput' string hook 'fixQmakeLibtool $prefix'
   5516 https://github.com/NixOS/nixpkgs/pull/290081: evaling 'fixupOutput' string hook 'if [ -z "${dontGzipMan-}" ]; then compressManPages "$prefix"; fi'
   5282 https://github.com/NixOS/nixpkgs/pull/290081: evaling 'fixupOutput' string hook 'if [ -z "${dontPatchELF-}" ]; then patchELF "$prefix"; fi'
   5516 https://github.com/NixOS/nixpkgs/pull/290081: evaling 'fixupOutput' string hook 'if [[ -z "${noAuditTmpdir-}" && -e "$prefix" ]]; then auditTmpdir "$prefix"; fi'
     17 https://github.com/NixOS/nixpkgs/pull/290081: evaling 'postFixup' string hook 'if [ -z "${dontAutoPatchelf-}" ]; then\n autoPatchelf -- $(for output in $(getAllOutputNames); do\n [ -e "${!output}" ] || continue\n echo "${!output}"\n done)\n fi'
      1 https://github.com/NixOS/nixpkgs/pull/290081: evaling 'postFixup' string hook 'mkdir -p $out/include'

To me, this suggests that each of these hooks ought to be made to fit under the previous function or sourcing hook logic (probably function)

... and that the cute, complicated loop actually works. Nice, @Qyriad.

philiptaron

Tested and works.

Qyriad · 2024-03-03T23:17:29Z

Is this ready to be squashed?

Edit: Nevermind! Thank you Raito!

ghost · 2024-03-08T15:25:25Z

i am seeing debug output when invoking nix-shell and i don't think i should see anything.
eg:

$ nix-shell -I nixpkgs=. -p bash
sourcing setup hook '/nix/store/h9lc1dpi14z7is86ffhl3ld569138595-audit-tmpdir.sh'
sourcing setup hook '/nix/store/m54bmrhj6fqz8nds5zcj97w9s9bckc9v-compress-man-pages.sh'
sourcing setup hook '/nix/store/wgrbkkaldkrlrni33ccvm3b6vbxzb656-make-symlinks-relative.sh'
sourcing setup hook '/nix/store/5yzw0vhkyszf2d179m0qfkgxmp5wjjx4-move-docs.sh'
sourcing setup hook '/nix/store/fyaryjvghbkpfnsyw97hb3lyb37s1pd6-move-lib64.sh'
sourcing setup hook '/nix/store/kd4xwxjpjxi71jkm6ka0np72if9rm3y0-move-sbin.sh'
sourcing setup hook '/nix/store/pag6l61paj1dc9sv15l7bm5c17xn5kyk-move-systemd-user-units.sh'
sourcing setup hook '/nix/store/jivxp510zxakaaic7qkrb7v1dd2rdbw9-multiple-outputs.sh'
sourcing setup hook '/nix/store/ilaf1w22bxi6jsi45alhmvvdgy4ly3zs-patch-shebangs.sh'
sourcing setup hook '/nix/store/cickvswrvann041nqxb0rxilc46svw1n-prune-libtool-files.sh'
sourcing setup hook '/nix/store/xyff06pkhki3qy1ls77w10s0v79c9il0-reproducible-builds.sh'
sourcing setup hook '/nix/store/ngg1cv31c8c7bcm2n8ww4g06nq7s4zhm-set-source-date-epoch-to-latest.sh'
sourcing setup hook '/nix/store/wmknncrif06fqxa16hpdldhixk95nds0-strip.sh'
sourcing setup hook '/nix/store/8dylc060lmn314b8wmz9bzm8f1dxv1n6-clang-wrapper-16.0.6/nix-support/setuphook'
sourcing setup hook '/nix/store/z46kig749819lcaz5sdbklnmx0bndlwg-cctools-binutils-darwin-wrapper-16.0.6-973.0.1/nix-support/setuphook'
calling 'envHostHostHook' function hook 'ccWrapper_addCVars' /nix/store/h9lc1dpi14z7is86ffhl3ld569138595-audit-tmpdir.sh
calling 'envHostHostHook' function hook 'bintoolsWrapper_addLDVars' /nix/store/h9lc1dpi14z7is86ffhl3ld569138595-audit-tmpdir.sh
calling 'envHostHostHook' function hook 'ccWrapper_addCVars' /nix/store/m54bmrhj6fqz8nds5zcj97w9s9bckc9v-compress-man-pages.sh
calling 'envHostHostHook' function hook 'bintoolsWrapper_addLDVars' /nix/store/m54bmrhj6fqz8nds5zcj97w9s9bckc9v-compress-man-pages.sh
calling 'envHostHostHook' function hook 'ccWrapper_addCVars' /nix/store/wgrbkkaldkrlrni33ccvm3b6vbxzb656-make-symlinks-relative.sh
calling 'envHostHostHook' function hook 'bintoolsWrapper_addLDVars' /nix/store/wgrbkkaldkrlrni33ccvm3b6vbxzb656-make-symlinks-relative.sh
[...]

using a8149b5

In NixOS#290081 it came to attention that autoPatchelfHook is one of if not the only hook in Nixpkgs that is a multiline string expression. Almost all hooks are functions, which guard with something like `if [ -z "${dontDoTheThing-}" ]; then ...` in the function, or single-line strings which include that guard inline and then call the real function, e.g. `if [ -z "${dontDoTheThing-} ]; then doTheThing; fi`. This commit moves autoPatchelfHook to the former, which seems to be the most common style now.

stdenv: log build hooks as they run

eb28e5e

Qyriad requested a review from Ericson2314 as a code owner February 20, 2024 01:08

github-actions bot added 8.has: documentation 6.topic: stdenv Standard environment labels Feb 20, 2024

NixOSInfra added the 12. first-time contribution This PR is the author's first one; please be gentle! label Feb 20, 2024

ofborg bot added 10.rebuild-darwin-stdenv This PR causes stdenv to rebuild 10.rebuild-linux-stdenv This PR causes stdenv to rebuild 10.rebuild-darwin: 501+ 10.rebuild-darwin: 5001+ 10.rebuild-linux: 501+ 10.rebuild-linux: 5001+ labels Feb 20, 2024

fogti reviewed Feb 24, 2024

View reviewed changes

pkgs/stdenv/generic/setup.sh Outdated Show resolved Hide resolved

pkgs/stdenv/generic/setup.sh Outdated Show resolved Hide resolved

Qyriad requested a review from fogti February 26, 2024 08:50

philiptaron reviewed Feb 27, 2024

View reviewed changes

prev: per-review: reword comment regarding logging of implicit hooks

ff372db

Addresses the following review comment: NixOS#290081 (comment) This will be squashed into the previous commit pending review. Co-authored-by: Philip Taron <philip.taron@gmail.com>

philiptaron approved these changes Feb 28, 2024

View reviewed changes

RaitoBezarius approved these changes Mar 3, 2024

View reviewed changes

RaitoBezarius merged commit 241ca50 into NixOS:staging Mar 3, 2024
23 checks passed

ghost mentioned this pull request Mar 10, 2024

Revert "stdenv: log build hooks as they run" #294625

Merged

Qyriad mentioned this pull request Mar 11, 2024

autoPatchelfHook: move multiline hook into a function #295099

Merged

13 tasks

Qyriad mentioned this pull request May 9, 2024

stdenv: log hooks as they run (take II) #310387

Merged

13 tasks

tie mentioned this pull request Jul 17, 2024

wrapCC, wrapBintools: use absolute paths #314920

Draft

13 tasks

This was referenced Jul 31, 2024

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

Closed

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

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

stdenv: log build hooks as they run #290081

stdenv: log build hooks as they run #290081

Qyriad commented Feb 20, 2024 •

edited

Loading

IreneKnapp commented Feb 24, 2024

Qyriad commented Feb 26, 2024

philiptaron left a comment

philiptaron Feb 27, 2024

Qyriad Feb 27, 2024 •

edited

Loading

philiptaron Feb 27, 2024

Qyriad Feb 27, 2024 •

edited

Loading

philiptaron Feb 27, 2024

Qyriad Feb 27, 2024

philiptaron commented Feb 28, 2024

philiptaron left a comment

Qyriad commented Mar 3, 2024 •

edited

Loading

ghost commented Mar 8, 2024 •

edited by ghost

Loading

stdenv: log build hooks as they run #290081

stdenv: log build hooks as they run #290081

Conversation

Qyriad commented Feb 20, 2024 • edited Loading

Description of changes

Things done

IreneKnapp commented Feb 24, 2024

Qyriad commented Feb 26, 2024

philiptaron left a comment

Choose a reason for hiding this comment

philiptaron Feb 27, 2024

Choose a reason for hiding this comment

Qyriad Feb 27, 2024 • edited Loading

Choose a reason for hiding this comment

philiptaron Feb 27, 2024

Choose a reason for hiding this comment

Qyriad Feb 27, 2024 • edited Loading

Choose a reason for hiding this comment

philiptaron Feb 27, 2024

Choose a reason for hiding this comment

Qyriad Feb 27, 2024

Choose a reason for hiding this comment

philiptaron commented Feb 28, 2024

philiptaron left a comment

Choose a reason for hiding this comment

Qyriad commented Mar 3, 2024 • edited Loading

ghost commented Mar 8, 2024 • edited by ghost Loading

Qyriad commented Feb 20, 2024 •

edited

Loading

Qyriad Feb 27, 2024 •

edited

Loading

Qyriad Feb 27, 2024 •

edited

Loading

Qyriad commented Mar 3, 2024 •

edited

Loading

ghost commented Mar 8, 2024 •

edited by ghost

Loading