Package: guix;
Reported by: ludo <at> gnu.org (Ludovic Courtès)
Date: Thu, 29 Mar 2018 15:19:02 UTC
Severity: normal
To reply to this bug, email your comments to 30986 AT debbugs.gnu.org.
Toggle the display of automated, internal messages from the tracker.
View this report as an mbox folder, status mbox, maintainer mbox
bug-guix <at> gnu.org:bug#30986; Package guix.
(Thu, 29 Mar 2018 15:19:02 GMT) Full text and rfc822 format available.ludo <at> gnu.org (Ludovic Courtès):bug-guix <at> gnu.org.
(Thu, 29 Mar 2018 15:19:02 GMT) Full text and rfc822 format available.Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):
From: ludo <at> gnu.org (Ludovic Courtès) To: bug-guix <at> gnu.org Subject: ‘guix substitute’ spins forever Date: Thu, 29 Mar 2018 17:18:40 +0200
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’.
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.