bug#30986: ‘guix substitute’ spins forever

[Ludovic Courtès]

I’ve stumbled upon a situation where ‘guix substitute’ would spin
endlessly.  Tracing the ‘guix substitute’ process shows that the
following two “info” queries would happen in a loop:

--8<---------------cut here---------------start------------->8---
read(0, "info /gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0 \n", 4096) 
= 60
openat(AT_FDCWD, 
"/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxey3r7suq2a65qr2ulq/cwmia787gmr4pypna6na1nfirqlr8y0p",
 O_RDONLY) = 13
fstat(13, {st_mode=S_IFREG|0600, st_size=1288, ...}) = 0
lseek(13, 0, SEEK_CUR)                  = 0
read(13, "(narinfo (version 2) (cache-uri \"https://berlin.guixsd.org\";) (date 
1522315393) (ttl 3888000) (value \"StorePath: 
/gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0\\nURL: 
nar/gzip/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0\\nCompression: 
gzip\\nNarHash: 
sha256:039i94jrmfsvn859kjarcmqzabs3nspmbz912gy03p0v6n64dr56\\nNarSize: 
98156824\\nReferences: 03j2yq30pcd2h17np0liarb2jdijg8y4-bash-static-4.4.19 
6v2lw5wkb36lwcky5x4i5ris08jabihs-glibc-2.27 asm7j8dm594ljjv"..., 4096) = 1288
close(13)                               = 0
write(1, "/gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0\n", 54) = 54
write(1, "/gnu/store/rvmhl8kb58zsj6pg2i2ha8f1dmx8wvm6-gcc-5.5.0.drv\n", 58) = 58
write(1, "5\n", 2)                      = 2
write(1, "/gnu/store/03j2yq30pcd2h17np0liarb2jdijg8y4-bash-static-4.4.19\n", 
63) = 63
write(1, "/gnu/store/6v2lw5wkb36lwcky5x4i5ris08jabihs-glibc-2.27\n", 55) = 55
write(1, "/gnu/store/asm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib\n", 58) = 58
write(1, "/gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0\n", 54) = 54
write(1, "/gnu/store/s4nzclq0ma3v19lvg84z8c7nqys9w3ai-zlib-1.2.11\n", 56) = 56
write(1, "35550259\n", 9)               = 9
write(1, "98156824\n", 9)               = 9
write(1, "\n", 1)                       = 1
read(0, "info /gnu/store/asm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib \n", 
4096) = 64
openat(AT_FDCWD, 
"/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxey3r7suq2a65qr2ulq/asm7j8dm594ljjvs0x90h8qivl5qdaz8",
 O_RDONLY) = 13
fstat(13, {st_mode=S_IFREG|0600, st_size=100, ...}) = 0
lseek(13, 0, SEEK_CUR)                  = 0
read(13, "(narinfo (version 2) (cache-uri \"https://berlin.guixsd.org\";) (date 
1522315402) (ttl 300) (value #f))", 4096) = 100
close(13)                               = 0
openat(AT_FDCWD, 
"/var/guix/substitute/cache/s3o7shxygzvof4rs6c3ed5hfifavpy43khzg5fyjdmrnlfk3b7va/asm7j8dm594ljjvs0x90h8qivl5qdaz8",
 O_RDONLY) = 13
fstat(13, {st_mode=S_IFREG|0600, st_size=105, ...}) = 0
lseek(13, 0, SEEK_CUR)                  = 0
read(13, "(narinfo (version 2) (cache-uri \"https://mirror.hydra.gnu.org\";) 
(date 1522315667) (ttl 10800) (value #f))", 4096) = 105
close(13)                               = 0
write(1, "\n", 1)                       = 1
--8<---------------cut here---------------end--------------->8---

The two store items being requested are outputs of the same derivations:

--8<---------------cut here---------------start------------->8---
$ head -c200 /gnu/store/rvmhl8kb58zsj6pg2i2ha8f1dmx8wvm6-gcc-5.5.0.drv
Derive([("lib","/gnu/store/asm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib","",""),("out","/gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0","","")],[("/gnu/store/0iwkdrk73cgpj1bq8jd66i8aca5hcm5v-
--8<---------------cut here---------------end--------------->8---

Another time, something similar happened in the middle of a series of
downloads:

--8<---------------cut here---------------start------------->8---
@ substituter-succeeded 
/gnu/store/wlkhfzz67h4wc3spj2fy8cvqaq8c60il-pkg-config-0.29.2
substitute: updating list of substitutes from 'https://berlin.guixsd.org'... 
100.0%
substitute: updating list of substitutes from 'https://mirror.hydra.gnu.org'... 
100.0%
@ substituter-started /gnu/store/68yb572zpkn26skh2dp1z91w2dnmrzzb-libgc-7.6.4 
/gnu/store/fbpk1zjcqd6p4ny8qx48mvlp4v7qfmld-guix-0.14.0-9.bdf0c64/libexec/guix/substitute
Downloading 
https://berlin.guixsd.org/nar/gzip/68yb572zpkn26skh2dp1z91w2dnmrzzb-libgc-7.6.4...
 libgc-7.6.4  398KiB                                                            
                                                                                
                                                    2.2MiB/s 00:00 
[##################] 100.0%

@ substituter-succeeded /gnu/store/68yb572zpkn26skh2dp1z91w2dnmrzzb-libgc-7.6.4
substitute: updating list of substitutes from 'https://berlin.guixsd.org'... 
100.0%

[… hangs here…]
--8<---------------cut here---------------end--------------->8---

While it’s hanging, ‘guix substitute’ receives this one query in a loop:

--8<---------------cut here---------------start------------->8---
read(0, "info /gnu/store/w91m22j33vxj3vvfa8lv04qjansdzr0d-libgc-7.6.4-debug 
\n", 4096) = 68
openat(AT_FDCWD, 
"/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxey3r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d",
 O_RDONLY) = 13
fstat(13, {st_mode=S_IFREG|0600, st_size=100, ...}) = 0
lseek(13, 0, SEEK_CUR)                  = 0
read(13, "(narinfo (version 2) (cache-uri \"https://berlin.guixsd.org\";) (date 
1522315814) (ttl 300) (value #f))", 4096) = 100
close(13)                               = 0
openat(AT_FDCWD, 
"/var/guix/substitute/cache/s3o7shxygzvof4rs6c3ed5hfifavpy43khzg5fyjdmrnlfk3b7va/w91m22j33vxj3vvfa8lv04qjansdzr0d",
 O_RDONLY) = 13
fstat(13, {st_mode=S_IFREG|0600, st_size=105, ...}) = 0
lseek(13, 0, SEEK_CUR)                  = 0
read(13, "(narinfo (version 2) (cache-uri \"https://mirror.hydra.gnu.org\";) 
(date 1522315814) (ttl 10800) (value #f))", 4096) = 105
close(13)                               = 0
write(1, "\n", 1)                       = 1
--8<---------------cut here---------------end--------------->8---

To unlock it, I did:

--8<---------------cut here---------------start------------->8---
$ sudo rm 
"/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxey3r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d"
# … narinfo gets redownloaded and file gets regenerated:
$ sudo cat 
"/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxey3r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d"
(narinfo (version 2) (cache-uri "https://berlin.guixsd.org";) (date 1522316403) 
(ttl 3888000) (value "StorePath: 
/gnu/store/w91m22j33vxj3vvfa8lv04qjansdzr0d-libgc-7.6.4-debug\nURL: 
nar/gzip/w91m22j33vxj3vvfa8lv04qjansdzr0d-libgc-7.6.4-debug\nCompression: 
gzip\nNarHash: 
sha256:0jrrknph5qs3n8v1prmmx4pgixhhdnqjh04i066c3fp12yx35hb7\nNarSize: 
1462960\nReferences: 68yb572zpkn26skh2dp1z91w2dnmrzzb-libgc-7.6.4 
6v2lw5wkb36lwcky5x4i5ris08jabihs-glibc-2.27 
asm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib 
cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0 
fbclk7l7fn4qh6nwi1xl1wbszhhj6yfd-libatomic-ops-7.6.2\nFileSize: 543891\nSystem: 
x86_64-linux\nDeriver: 
9c7ilc15k8p5b84lxhgn2jy6l6xgbdpj-libgc-7.6.4.drv\nSignature: 
1;berlin.guixsd.org;KHNpZ25hdHVyZSAKIChkYXRhIAogIChmbGFncyByZmM2OTc5KQogIChoYXNoIHNoYTI1NiAjRTBGRUExNkQ5ODU5Mjk1QjQ4N0IwOTc2RTVFRkIxNDUzRTdCOUVFNkJBNUFBRkY5NUFEQTg1REY5QUJENkI4QSMpCiAgKQogKHNpZy12YWwgCiAgKGVjZHNhIAogICAociAjMDY0MkZCQUYwRDExNDM2NTc3NUY1QTI2REU3NDYyOTMyQzg5RjhCM0U4RDg5MzQ4MzRBNTQwRDAwMEVBQTk5QiMpCiAgIChzICMwMzQ1RUFCMDM1MzBEMzRFOTEwNzVFMzFFMUFENjM4OEI3NDAwRTQxRjRBOTExRjg0RDE0NEQ3M0QxMkVCMzY5IykKICAgKQogICkKIChwdWJsaWMta2V5IAogIChlY2MgCiAgIChjdXJ2ZSBFZDI1NTE5KQogICAocSAjOEQxNTZGMjk1RDI0QjBEOUE4NkZBNTc0MUE4NDBGRjJEMjRGNjBGN0I2QzQxMzQ4MTRBRDU1NjI1OTcxQjM5NCMpCiAgICkKICApCiApCg==\n"))
--8<---------------cut here---------------end--------------->8---

… and the daemon went on to substitute libgc-7.6.4-debug.

This apparently has to do with multiple-output derivations where not all
of the outputs are substitutable.  The loop could come from
SubstitutionGoal::tryNext, which recurses:

    SubstitutablePathInfos infos;
    PathSet dummy(singleton<PathSet>(storePath));
    worker.store.querySubstitutablePathInfos(sub, dummy, infos);
    SubstitutablePathInfos::iterator k = infos.find(storePath);
    if (k == infos.end()) { tryNext(); return; }
    info = k->second;
    hasSubstitute = true;

Ludo’.