Sourcing setup hook *default hook* spam in writers/trivial builders

[Artturin]

Issue description

Thousands of lines of sourcing the default hooks during system upgrades

building '/nix/store/d9cbm028l5i1fgk2zflqw41f5cfcsv1s-50-coredump.conf.drv'...
sourcing setup hook '/nix/store/yq6n8b0mnk0qxzbs3ajsjcp8ziwqylrl-patchelf-0.15.0/nix-support/setup-hook'
sourcing setup hook '/nix/store/iks1pihvbilsh5sy8qvpd638k422w9i8-update-autotools-gnu-config-scripts-hook/nix-support/setup-hook'
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/gps9qrh99j7g02840wv5x78ykmz30byp-strip.sh'
building '/nix/store/cn0ybnlsililnkkzqfs9pi6cvn9plxhf-tmpfiles.d.drv'...
sourcing setup hook '/nix/store/yq6n8b0mnk0qxzbs3ajsjcp8ziwqylrl-patchelf-0.15.0/nix-support/setup-hook'
sourcing setup hook '/nix/store/iks1pihvbilsh5sy8qvpd638k422w9i8-update-autotools-gnu-config-scripts-hook/nix-support/setup-hook'
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-symlink
...

#310387

CC
@Qyriad @philiptaron

[Atemu]

This might be useful to have on some occasions but IMO it should only happen when a debug env var is set.

[Artturin]

Maybe we need a special @nix thing like nixLog "@nix { \"action\": \"setPhase\", \"phase\": \"$curPhase\" }" for debug logs which then follows some nix flag which works for building and for nix log

[philiptaron]

Yeah, I really like the hook-logging PR, but it is too much spam at the moment.

There are essentially two ways to go, as I see it.

1. Revert stdenv: log hooks as they run (take II) #310387 and leave a stub with a pointer to it in the stdenv -- "if you're interested in getting more logging, try this!". This is the easy option.
2. Keep the hook logging under some other Nix environment variable. NIX_DEBUG was suggested on Matrix. I don't have a good sense for what the right choice is, and what's exposed through all the various ways Nix derivations are realized.

Any others?

[Qyriad]

Maybe we need a special @nix thing like nixLog "@nix { "action": "setPhase", "phase": "$curPhase" }" for debug logs which then follows some nix flag which works for building and for nix log

This is actually partially a thing. The Nix log FD can take specific verbosity levels:

https://github.com/NixOS/nix/blob/8ce4287409319e04f46ed1352deb956c30e35fc6/src/libutil/logging.cc#L327-L329

I seem to recall this not showing up in nix log, though, which iirc was why I didn't go for that in the first place. I didn't want to use NIX_DEBUG, since using that changes the derivation, making it impractical for "passive viewing".

Another idea is that we could change the implementation to summarize hooks there are a lot of, or especially default hooks. e.g., instead of

sourcing setup hook '/nix/store/yq6n8b0mnk0qxzbs3ajsjcp8ziwqylrl-patchelf-0.15.0/nix-support/setup-hook'
sourcing setup hook '/nix/store/iks1pihvbilsh5sy8qvpd638k422w9i8-update-autotools-gnu-config-scripts-hook/nix-support/setup-hook'
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'

Maybe we could have:

sourced 14 setup hooks: audit-tmpdir.sh, compress-man-pages.sh, make-symlinks-relative.sh, move-docs.sh, move-lib64.sh, move-sbin.sh, move-systemd-user-units.sh, multiple-outputs.sh, patch-shebangs.sh, prune-libtool-files.sh, reproducible-builds.sh, set-source-date-epoch-to-latest.sh

And then those could be expanded to one-per-line with NIX_DEBUG?

[Atemu]

I didn't want to use NIX_DEBUG, since using that changes the derivation, making it impractical for "passive viewing".

Couldn't we turn this into some sort of impure env var that trusted users would be allowed to pass into the sandbox?

I seem to recall this not showing up in nix log, though, which iirc was why I didn't go for that in the first place.

We should probably fix that instead.

Another idea is that we could change the implementation to summarize hooks there are a lot of, or especially default hooks. e.g., instead of

That's better but there's tonnes of these trivial builders/writers in a typical system closure. Even just one line each would amount to significant spam.

[Atemu]

Another idea that just occurred to me would be to only print this info in non-trivial builders because. Non-trivial builds usually have tons of other output and don't occur as frequently as trivial builders, making these few lines a non-issue.

Perhaps even better though, we could only print the setup hooks when the set of setup hooks differs from the default. This way an empty output would imply that the default set of setup hooks were run.

Can trivial builders (non-mkDerivation) even have non-default setup hooks?

[emilazy]

For what it’s worth, I suspect this problem is worse on Darwin. Like, look at the sheer number of calling 'envHostTargetHook' function hook 'useSystemCoreFoundationFramework' lines in this log.

[Qyriad]

Disabling hook logging for trivial builds sounds reasonable to me, though it does raise the question of why there are so many specific-use default hooks in the first place.

The env* hooks are also disproportionally numerous and probably also good candidates for summarization.

[Atemu]

I think that's a topic for another issue.

[hraban]

I didn't want to use NIX_DEBUG, since using that changes the derivation, making it impractical for "passive viewing".

Couldn't we turn this into some sort of impure env var that trusted users would be allowed to pass into the sandbox?

+1 from me on this, I always felt it weird having to change a derivation to get extra debug output. This basically makes debugging stdenv impossible (at least on darwin).

[rycee]

For reference, this logging is pretty disruptive for HM CI runs, see e.g. https://github.com/nix-community/home-manager/actions/runs/10135333457.

[Atemu]

I propose we only enable this when NIX_DEBUG is set until a better solution is found. Causing this degree of log spam is not acceptable for mere "passive viewing" improvements IMHO.

[tie]

-1 on completely disabling these logs without NIX_DEBUG ≥ 1, I find them actually useful—even (and especially) for a successful build, it makes it easy to review in nix log that hooks are sourced in the correct order, there are no unintended hooks, etc.

I also don’t find them spammy. Yes, they offset the package build logs by a few hundred lines at worst (depending on the number of dependencies), but for any non-trivial package ./configure && make is a lot more verbose. In addition to that, these logs are already suppressed for development shells (where NIX_LOG_FD is not set).

I agree that it makes sense to suppress these logs for trivial builders where the set of dependencies is usually predefined.

[emilazy]

I feel like this is controversial enough that it makes sense to partially roll back – leaving the NIX_DEBUG option in – until we can come up with a nicer opt‐in/opt‐out solution. I’m not denying its utility, but I definitely agree with people saying this makes build log consumption a lot less pleasant, especially on macOS. Although maybe after next staging cycle when the CoreFoundation hook goes away it’ll be less bad…

[philiptaron]

No matter what, any change to either revert or mutate will go through a staging cycle because it causes a mass rebuild.

[SuperSandro2000]

I also suspect this to slow down remote builds because of the amount of bandwith being used by those logs 😓

[philiptaron]

I've made a super speculative attempt at fixing this issue in #331383. Please take a look.

[oxalica]

I propose we only enable this when NIX_DEBUG is set until a better solution is found.

This sounds weird to me. I'm expecting the frontend Nix handling the filtration, that's why we need NIX_LOG_FD for "more structural" logs instead of printing everything to stdout/stderr, yes? Also that, opt-in logs that requiring rebuilds to enable effectively means no logs in production at all.

[Atemu]

I'm expecting the frontend Nix handling the filtration, that's why we need NIX_LOG_FD for "more structural" logs instead of printing everything to stdout/stderr

That would be an example for a "better solution". I'm all for such a better solution but a lot of time will pass until it's usable, time in which every user is spammed with 100s of useless log lines, burying actual issues and causing confusion.

Also that, opt-in logs that requiring rebuilds to enable effectively means no logs in production at all.

That represents the previous status quo and my proposal is indeed to regress to that previous status quo.

I don't really see what's "weird" about that.

[philiptaron]

Folks interested in this topic: I could use reviews on #331560. The next staging -> staging-next merge is happening soon.

[philiptaron]

When #331560 lands in master (it's part of the current staging-next PR) there will be no more hook logging unless you opt in to $NIX_DEBUG at 4 or greater.

I'm closing this issue as a result.