‘guix substitute’ spins forever

  • Open
  • quality assurance status badge
Details
2 participants
  • Ludovic Courtès
  • Simon Tournier
Owner
unassigned
Submitted by
Ludovic Courtès
Severity
normal

Debbugs page

L
L
Ludovic Courtès wrote on 29 Mar 2018 08:18
‘guix substitute’ spins forever
(address . bug-guix@gnu.org)
87po3mvrjj.fsf@gnu.org
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:

Toggle snippet (31 lines)
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:

Toggle snippet (4 lines)
$ 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:

Toggle snippet (13 lines)
@ 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:

Toggle snippet (14 lines)
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:

Toggle snippet (6 lines)
$ 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;

Ludo’.
S
S
Simon Tournier wrote on 16 Jun 03:05 -0700
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 30986@debbugs.gnu.org)
87ldps80i6.fsf@gmail.com
Hi Ludo,

Digging into the bug tracker for some triage, I hit this:


and it reminds me our recent discussion here:


WDYT?

On Thu, 29 Mar 2018 at 17:18, ludo@gnu.org (Ludovic Courtès) wrote:

Toggle quote (94 lines)
> 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
L
L
Ludovic Courtès wrote on 16 Jun 06:23 -0700
(address . 30986@debbugs.gnu.org)(name . Simon Tournier)(address . zimon.toutoune@gmail.com)
87wm9bddlp.fsf@gnu.org
Hi,

ludo@gnu.org (Ludovic Courtès) writes:

Toggle quote (4 lines)
> 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:

It may have been due to https://issues.guix.gnu.org/31785 (now fixed),
or it could be something else.

Let’s keep it around for now.

Thanks for the triage work!

Ludo’.
?
Your comment

Commenting via the web interface is currently disabled.

To comment on this conversation send an email to 30986@patchwise.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 30986
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch