Nix 2.32 queries cache.nixos.org even when local substituter has a path #14836
Description
Describe the bug
I run Nix tests in CI where I build a local cache with mkBinaryCache, and then use it to test Nix builds in fresh environments.
I have a test to make sure that these builds hit the local cache and don't download from cache.nixos.org. But between version 2.31 and 2.32 of Nix, something changed. When I turn on verbose logs, I see Nix doing the following:
- Querying the local substituter for a path
- Querying
cache.nixos.orgfor the same path (!) - Downloading the
.narinfofromcache.nixos.org. (!) - Ultimately copying the path from the local substituter
Steps 2 and 3 here are new and not desirable, because I don't want unnecessary network calls going to cache.nixos.org.
To illustrate this, I ran the build with -vv --debug and grepped the output for a randomly chosen path, /nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3. You can see the output for 2.31 and 2.32 below.
Nix 2.31 output
checking substituter 'file:///binary-substituter-0' for path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
querying info about '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3' on 'file:///binary-substituter-0'...
/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3
checking substituter 'file:///binary-substituter-0' for path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': created
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': woken up
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': init
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': trying next substituter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': in final_awaiter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': all references realised
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': woken up
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': in final_awaiter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': trying to run
copying path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3' from 'file:///binary-substituter-0'...
locking path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
lock acquired on '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3.lock'
lock released on '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3.lock'
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': got EOF
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': woken up
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': substitute finished
substitution of path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3' succeeded
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': done
substitution of '/nix/store/g74j0j5c9fjcx68b3m9c128gc14845jw-gnutls-3.8.9': waitee 'substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'' done; 10 left
substitution of '/nix/store/w86hjmaxv9izw2gvkprl6ciabws8b19y-libpsl-0.21.5': waitee 'substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'' done; 3 left
substitution of '/nix/store/2q1vszdygbs1icp1cd18a4d11zcsc97y-libidn2-2.3.8': waitee 'substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'' done; 0 left
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': in final_awaiter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': goal destroyed
Nix 2.32 output
checking substituter 'file:///binary-substituter-0' for path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
querying info about '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3' on 'file:///binary-substituter-0'...
checking substituter 'https://cache.nixos.org' for path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
querying info about '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3' on 'https://cache.nixos.org'...
downloading 'https://cache.nixos.org/7r0k7ywzmgkscjxgzmgwsng0545h8id6.narinfo'...
starting download of https://cache.nixos.org/7r0k7ywzmgkscjxgzmgwsng0545h8id6.narinfo
finished download of 'https://cache.nixos.org/7r0k7ywzmgkscjxgzmgwsng0545h8id6.narinfo'; curl status = 0, HTTP status = 200, body = 567 bytes, duration = 0.01 s
/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3
checking substituter 'file:///binary-substituter-0' for path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
checking substituter 'https://cache.nixos.org' for path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': created
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': woken up
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': init
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': trying next substituter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': in final_awaiter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': all references realised
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': woken up
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': in final_awaiter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': trying to run
copying path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3' from 'file:///binary-substituter-0'...
locking path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'
lock acquired on '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3.lock'
lock released on '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3.lock'
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': got EOF
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': woken up
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': substitute finished
substitution of path '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3' succeeded
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': done
substitution of '/nix/store/g74j0j5c9fjcx68b3m9c128gc14845jw-gnutls-3.8.9': waitee 'substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'' done; 10 left
substitution of '/nix/store/w86hjmaxv9izw2gvkprl6ciabws8b19y-libpsl-0.21.5': waitee 'substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'' done; 3 left
substitution of '/nix/store/2q1vszdygbs1icp1cd18a4d11zcsc97y-libidn2-2.3.8': waitee 'substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3'' done; 0 left
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': in final_awaiter
substitution of '/nix/store/7r0k7ywzmgkscjxgzmgwsng0545h8id6-libunistring-1.3': goal destroyed
Steps To Reproduce
This is tricky to reproduce because it involves a bunch my test infrastructure to set up. If maintainers would like then I can work on coming up with an easy repro.
Expected behavior
Nix should use the first working substituter it finds by working in priority order, and not send unnecessary network calls to other ones.
Metadata
nix-env (Nix) 2.32.3
Additional context
This seems like a regression to me. There's nothing in the release notes that would seem to explain it.
The only other explanation I can think of is that Nix 2.32 doesn't like the local binary cache created by mkBinaryCache in some way. (But it can't dislike it too much, because it still ultimately ends up downloading the path from there.)
I was looking around and I saw that #13301 might be a possible suspect as a PR that changed how the substituter logic works? It was merged on September 12, so I'm guessing it made it into release 2.32 which came out in early October? No mention about it in the release notes though.
Checklist
- checked [latest Nix manual] ([source])
- checked [open bug issues and pull requests] for possible duplicates
Add 👍 to issues you find important.