Nix sometimes does not use configured substituters after a garbage collection

[the-sun-will-rise-tomorrow]

Describe the bug

Nix sometimes does not use configured substituters after a garbage collection.

Steps To Reproduce

1. Configure a substituter and a post-build-hook to push to that substituter.
2. Build a derivation. Example: nix-build -vv --no-out-link -E 'let pkgs = import <nixpkgs> {} ; in pkgs.stdenv.mkDerivation { name="test1237"; dontUnpack = true; buildPhase = "echo OK > $out"; }'
   • Nix should build it locally and then upload it to the substituter.
3. Collect garbage (nix-store --gc)
4. Build the same derivation as in step 2 again.

Expected behavior

It should grab it from the binary cache, something like this:

instantiated 'test1235' -> '/nix/store/3y576xwc3ir589k90n7y07h5rn9frbip-test1235.drv'
this path will be fetched (0.00 MiB download, 0.00 MiB unpacked):
  /nix/store/r4sfdhrgsfbca8cac8a5y7ks29x5k02i-test1235
copying path '/nix/store/r4sfdhrgsfbca8cac8a5y7ks29x5k02i-test1235' from 'http://nix-cache.example.com:5000'...
downloading 'http://nix-cache.example.com:5000/nar/0yvmy06j6qpv17b79hh9wj6g26h7cmm5xm7aqgpwikq7ng7q4fn6.nar?hash=r4sfdhrgsfbca8cac8a5y7ks29x5k02i%27...
substitution of path '/nix/store/r4sfdhrgsfbca8cac8a5y7ks29x5k02i-test1235' succeeded
/nix/store/r4sfdhrgsfbca8cac8a5y7ks29x5k02i-test1235

Actual behavior

For some reason it sometimes doesn't check the substituter at all.

instantiated 'test1237' -> '/nix/store/qfbgapag178y9slqnxrzldcm1fkmfv65-test1237.drv'
this derivation will be built:
  /nix/store/qfbgapag178y9slqnxrzldcm1fkmfv65-test1237.drv
these 45 paths will be fetched (320.66 MiB download, 320.66 MiB unpacked):
  /nix/store/7zqx95qyg38fic8mzk0nxz06ag3jkh12-acl-2.3.1
  /nix/store/v3kjfcaysin90dqyna1rwgnxsf3pg7fz-attr-2.5.1
... continues to build the derivation ...

nix-env --version output

nix-env (Nix) 2.17.1

Additional context

Trying to setup up a binary cache at $dayjob and it's not looking good :(

Priorities

Add :+1: to issues you find important.

[cole-h]

You may want to rerun the second invocation with --narinfo-cache-negative-ttl 0. It's likely Nix is querying the substituter, noticing that it doesn't have the path, and then storing the fact it wasn't there in the database (so that it doesn't need to do slow networking every time and ask the substituter for a path it doesn't (didn't) have).

[the-sun-will-rise-tomorrow]

Yes, that was it. Thank you!

Where is that persisted? I tried to delete ~/.cache/nix before every invocation (which didn't work) and checked every file in /nix/var and couldn't find any relevant mentions of the cache.

[the-sun-will-rise-tomorrow]

Also, would it make sense to add some logging for this? I couldn't see any explanation for why it was making that decision even at the maximum log level.

[cole-h]

Something to keep in mind is that, when running Nix as a daemon, it is essentially running as root, so you'd also need to have cleared ~root/.cache/nix (usually that's just /root/.cache/nix).

EDIT: But yeah, if there isn't already logging about this, there probably should be. I can try to have a look at that later.

[the-sun-will-rise-tomorrow]

Something to keep in mind is that, when running Nix as a daemon, it is essentially running as root, so you'd also need to have cleared ~root/.cache/nix (usually that's just /root/.cache/nix).

I did not think to look there. Thank you!