Hi Ludo,
Digging into the bug tracker for some triage, I hit this:
https://issues.guix.gnu.org/issue/30986
and it reminds me our recent discussion here:
https://codeberg.org/guix/guix/issues/430
WDYT?
On Thu, 29 Mar 2018 at 17:18, [email protected] (Ludovic Courtès) wrote:
> 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:
>
> 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
>
>
> The two store items being requested are outputs of the same derivations:
>
> $ 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-
>
>
> Another time, something similar happened in the middle of a series of
> downloads:
>
> @ 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…]
>
>
> While it’s hanging, ‘guix substitute’ receives this one query in a loop:
>
> 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
>
>
> To unlock it, I did:
>
> $ 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"))
>
> … 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;
BTW, if it appears to you unrelated, what is the status of this old bug
with only one message? :-)
Cheers,
simon
