Nix: `nix build -L` prints each log-line twice when using a `ssh-ng` store.

[Ma27]

Describe the bug

When building a derivation with a ssh-ng store and allowing nix build to print all log-lines using -L, I get every log-line twice.

Steps To Reproduce

1. Configure an arbitrary remote SSH-host to a machine with a running nix-daemon (I reproduced this with the aarch64 build-box and my personal build-server).
2. Run e.g. nix build -f . package -L --option experimental-features nix-command --store ssh-ng://builder

The log-output looks e.g. like this when building nixops from a recent nixpkgs:

Finished executing pipInstallPhase
nixops> Finished executing pipInstallPhase
post-installation fixup
nixops> post-installation fixup
shrinking RPATHs of ELF executables and libraries in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7
nixops> shrinking RPATHs of ELF executables and libraries in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7
gzipping man pages under /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/share/man/
nixops> gzipping man pages under /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/share/man/
strip is /nix/store/3b3ighb83nhifa1v4n7855hlbdl1mhf9-binutils-2.31.1/bin/strip
nixops> strip is /nix/store/3b3ighb83nhifa1v4n7855hlbdl1mhf9-binutils-2.31.1/bin/strip
stripping (with command strip and flags -S) in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/lib  /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/bin
nixops> stripping (with command strip and flags -S) in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/lib  /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/bin
patching script interpreter paths in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7
nixops> patching script interpreter paths in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7
/nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/share/nix/nixops/generate-ec2-properties.py: interpreter directive changed from " /usr/bin/env python2" to "/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18/bin/python2"
nixops> /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/share/nix/nixops/generate-ec2-properties.py: interpreter directive changed from " /usr/bin/env python2" to "/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18/bin/python2"
checking for references to /build/ in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7...
nixops> checking for references to /build/ in /nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7...
Rewriting #! /nix/store/kgp3vq8l9yb8mzghbw83kyr3f26yqvsz-bash-4.4-p23/bin/bash -e to #!/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18
nixops> Rewriting #! /nix/store/kgp3vq8l9yb8mzghbw83kyr3f26yqvsz-bash-4.4-p23/bin/bash -e to #!/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18
Rewriting #!/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18/bin/python2.7 to #!/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18
nixops> Rewriting #!/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18/bin/python2.7 to #!/nix/store/l9in14pg5smp2gw1mys40zw0r8k8h7la-python-2.7.18
wrapping `/nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/bin/.nixops-wrapped'...
nixops> wrapping `/nix/store/p5fpq9a68izn34f9xsw0p69s299dkvl5-nixops-1.7/bin/.nixops-wrapped'...
Executing pythonRemoveTestsDir
nixops> Executing pythonRemoveTestsDir
Finished executing pythonRemoveTestsDir
nixops> Finished executing pythonRemoveTestsDir
running install tests
nixops> running install tests
NixOps 1.7
nixops> NixOps 1.7
pythonCatchConflictsPhase
nixops> pythonCatchConflictsPhase
pythonRemoveBinBytecodePhase
nixops> pythonRemoveBinBytecodePhase
pythonImportsCheckPhase
nixops> pythonImportsCheckPhase
Executing pythonImportsCheckPhase
nixops> Executing pythonImportsCheckPhase
[1 built, 0.0 MiB DL]

Expected behavior

I'd expect to only get the log-lines prefixed with nixops>. The same log-message without the prefix shouldn't appear.

nix-env --version output

nix-env (Nix) 2.4 (to be precise, I tested on 625868b33dab37c0750081843be8091e22808376 in my local git-checkout of Nix).

Additional context

• When using ssh://builder as store, the issue doesn't exist. I'm not 100% sure why yet, unfortunately.
• The messages prefixed with nixops> are sent from the remote daemon as STDERR_RESULT and therefore properly shown by the progress-bar.
• The non-prefixed duplications are sent as STDERR_NEXT from remote and directly printed within the logger implementation in remote-store.cc
• The culprit is in the build.cc where a log-line is transmitted twice (via act->result and via printError) if verboseBuild == true. Patching Nix on the remote machine by removing the printError-statement in line 4137 seems to fix the issue.

Please note that I'm not exactly sure how to proceed here. verboseBuild doesn't seem to be an option since it's hard-coded in libstore/globals.hh, also modifying this value may have further implications.

Also, the SSHStore-implementation for ssh-ng basically starts a nix-daemon via ssh remotely, so AFAICS there's no way on the remote side to determine if a ssh-ng store is used where the problem occurs.

I decided to open an issue first to gather some more input, but I'm happy to provide a patch to fix this in the end :)

CCing some folks who may know about ssh-ng @edolstra @grahamc @lheckemann

[lheckemann]

Yep, have also observed this. It never bothered me enough to make an issue for it :sweat_smile:

[LnL7]

Same here, never took the time to look into it.

[bhipple]

Hah, also in the same category of noticing it and ignoring it. Perhaps the nix community has a systemic problem of having too much tolerance for pain :sweat_smile:

[lheckemann]

Reopened because the fix was reverted https://github.com/NixOS/nix/pull/3558#issuecomment-624022065 (it broke hash-mismatch errors)

[Ma27]

It seems as it is only reproducible when having nixUnstable locally and on the remote side where ssh-ng connects to Nix 2.3. If both sides use nixUnstable, I don't have this problem anymore.

[bjornfor]

I get every log line duplicated with a local build (no ssh-ng):

$ nix-build -A nixUnstable
/nix/store/kqjc91cjfishvy924wzhv40a0k14s6rk-nix-2.4pre20201102_550e11f

$ ./result/bin/nix-build --version
nix-build (Nix) 2.4pre20201102_550e11f

$ ./result/bin/nix-build --no-out-link -A bash-completion --builders ''
warning: unknown setting 'extra-sandbox-paths'
this derivation will be built:
  /nix/store/q9ic2rzdqbrixkv9m0iwmxz6rxswzgpw-bash-completion-2.10.drv
building '/nix/store/q9ic2rzdqbrixkv9m0iwmxz6rxswzgpw-bash-completion-2.10.drv'...
unpacking sources
unpacking sources
unpacking source archive /nix/store/jp6s0xnqv29ks6ginw1y5r6salg9fzm5-source
unpacking source archive /nix/store/jp6s0xnqv29ks6ginw1y5r6salg9fzm5-source
source root is source
source root is source
[...]

The nix-daemon is v2.3.6.

UPDATE: I think it's a separate issue, let's track that here.