From mboxrd@z Thu Jan 1 00:00:00 1970 From: ludo@gnu.org (Ludovic =?UTF-8?Q?Court=C3=A8s?=) Subject: bug#30986: =?UTF-8?Q?=E2=80=98guix_?= =?UTF-8?Q?substitute=E2=80=99?= spins forever Date: Thu, 29 Mar 2018 17:18:40 +0200 Message-ID: <87po3mvrjj.fsf@gnu.org> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Return-path: Received: from eggs.gnu.org ([2001:4830:134:3::10]:54232) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1f1ZKV-00005K-6C for bug-guix@gnu.org; Thu, 29 Mar 2018 11:19:08 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1f1ZKR-0006io-2v for bug-guix@gnu.org; Thu, 29 Mar 2018 11:19:07 -0400 Received: from debbugs.gnu.org ([208.118.235.43]:50925) by eggs.gnu.org with esmtps (TLS1.0:RSA_AES_128_CBC_SHA1:16) (Exim 4.71) (envelope-from ) id 1f1ZKQ-0006iJ-U1 for bug-guix@gnu.org; Thu, 29 Mar 2018 11:19:03 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1f1ZKQ-0004qS-Fz for bug-guix@gnu.org; Thu, 29 Mar 2018 11:19:02 -0400 Sender: "Debbugs-submit" Resent-Message-ID: Received: from eggs.gnu.org ([2001:4830:134:3::10]:54003) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1f1ZKC-0008JN-PT for bug-guix@gnu.org; Thu, 29 Mar 2018 11:18:50 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1f1ZK8-0006Nr-Nz for bug-guix@gnu.org; Thu, 29 Mar 2018 11:18:48 -0400 Received: from hera.aquilenet.fr ([2a0c:e300::1]:51140) by eggs.gnu.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.71) (envelope-from ) id 1f1ZK8-0006Lw-DH for bug-guix@gnu.org; Thu, 29 Mar 2018 11:18:44 -0400 Received: from localhost (localhost [127.0.0.1]) by hera.aquilenet.fr (Postfix) with ESMTP id AB8AB12AF3 for ; Thu, 29 Mar 2018 17:18:42 +0200 (CEST) Received: from hera.aquilenet.fr ([127.0.0.1]) by localhost (hera.aquilenet.fr [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 2lWRHn25yAio for ; Thu, 29 Mar 2018 17:18:41 +0200 (CEST) Received: from ribbon (unknown [193.50.110.67]) by hera.aquilenet.fr (Postfix) with ESMTPSA id 6CEAC12AF2 for ; Thu, 29 Mar 2018 17:18:41 +0200 (CEST) List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-guix-bounces+gcggb-bug-guix=m.gmane.org@gnu.org Sender: "bug-Guix" To: 30986@debbugs.gnu.org I=E2=80=99ve stumbled upon a situation where =E2=80=98guix substitute=E2=80= =99 would spin endlessly. Tracing the =E2=80=98guix substitute=E2=80=99 process shows tha= t the following two =E2=80=9Cinfo=E2=80=9D queries would happen in a loop: --8<---------------cut here---------------start------------->8--- read(0, "info /gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0 \n", 40= 96) =3D 60 openat(AT_FDCWD, "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3h= wbhxey3r7suq2a65qr2ulq/cwmia787gmr4pypna6na1nfirqlr8y0p", O_RDONLY) =3D 13 fstat(13, {st_mode=3DS_IFREG|0600, st_size=3D1288, ...}) =3D 0 lseek(13, 0, SEEK_CUR) =3D 0 read(13, "(narinfo (version 2) (cache-uri \"https://berlin.guixsd.org\") (d= ate 1522315393) (ttl 3888000) (value \"StorePath: /gnu/store/cwmia787gmr4py= pna6na1nfirqlr8y0p-gcc-5.5.0\\nURL: nar/gzip/cwmia787gmr4pypna6na1nfirqlr8y= 0p-gcc-5.5.0\\nCompression: gzip\\nNarHash: sha256:039i94jrmfsvn859kjarcmqz= abs3nspmbz912gy03p0v6n64dr56\\nNarSize: 98156824\\nReferences: 03j2yq30pcd2= h17np0liarb2jdijg8y4-bash-static-4.4.19 6v2lw5wkb36lwcky5x4i5ris08jabihs-gl= ibc-2.27 asm7j8dm594ljjv"..., 4096) =3D 1288 close(13) =3D 0 write(1, "/gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0\n", 54) =3D= 54 write(1, "/gnu/store/rvmhl8kb58zsj6pg2i2ha8f1dmx8wvm6-gcc-5.5.0.drv\n", 58)= =3D 58 write(1, "5\n", 2) =3D 2 write(1, "/gnu/store/03j2yq30pcd2h17np0liarb2jdijg8y4-bash-static-4.4.19\n"= , 63) =3D 63 write(1, "/gnu/store/6v2lw5wkb36lwcky5x4i5ris08jabihs-glibc-2.27\n", 55) = =3D 55 write(1, "/gnu/store/asm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib\n", 58)= =3D 58 write(1, "/gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0\n", 54) =3D= 54 write(1, "/gnu/store/s4nzclq0ma3v19lvg84z8c7nqys9w3ai-zlib-1.2.11\n", 56) = =3D 56 write(1, "35550259\n", 9) =3D 9 write(1, "98156824\n", 9) =3D 9 write(1, "\n", 1) =3D 1 read(0, "info /gnu/store/asm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib \n"= , 4096) =3D 64 openat(AT_FDCWD, "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3h= wbhxey3r7suq2a65qr2ulq/asm7j8dm594ljjvs0x90h8qivl5qdaz8", O_RDONLY) =3D 13 fstat(13, {st_mode=3DS_IFREG|0600, st_size=3D100, ...}) =3D 0 lseek(13, 0, SEEK_CUR) =3D 0 read(13, "(narinfo (version 2) (cache-uri \"https://berlin.guixsd.org\") (d= ate 1522315402) (ttl 300) (value #f))", 4096) =3D 100 close(13) =3D 0 openat(AT_FDCWD, "/var/guix/substitute/cache/s3o7shxygzvof4rs6c3ed5hfifavpy= 43khzg5fyjdmrnlfk3b7va/asm7j8dm594ljjvs0x90h8qivl5qdaz8", O_RDONLY) =3D 13 fstat(13, {st_mode=3DS_IFREG|0600, st_size=3D105, ...}) =3D 0 lseek(13, 0, SEEK_CUR) =3D 0 read(13, "(narinfo (version 2) (cache-uri \"https://mirror.hydra.gnu.org\")= (date 1522315667) (ttl 10800) (value #f))", 4096) =3D 105 close(13) =3D 0 write(1, "\n", 1) =3D 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-con= fig-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/libexe= c/guix/substitute Downloading https://berlin.guixsd.org/nar/gzip/68yb572zpkn26skh2dp1z91w2dnm= rzzb-libgc-7.6.4... libgc-7.6.4 398KiB = = 2.2MiB/s 00:0= 0 [##################] 100.0% @ substituter-succeeded /gnu/store/68yb572zpkn26skh2dp1z91w2dnmrzzb-libgc-7= .6.4 substitute: updating list of substitutes from 'https://berlin.guixsd.org'..= . 100.0% [=E2=80=A6 hangs here=E2=80=A6] --8<---------------cut here---------------end--------------->8--- While it=E2=80=99s hanging, =E2=80=98guix substitute=E2=80=99 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) =3D 68 openat(AT_FDCWD, "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3h= wbhxey3r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d", O_RDONLY) =3D 13 fstat(13, {st_mode=3DS_IFREG|0600, st_size=3D100, ...}) =3D 0 lseek(13, 0, SEEK_CUR) =3D 0 read(13, "(narinfo (version 2) (cache-uri \"https://berlin.guixsd.org\") (d= ate 1522315814) (ttl 300) (value #f))", 4096) =3D 100 close(13) =3D 0 openat(AT_FDCWD, "/var/guix/substitute/cache/s3o7shxygzvof4rs6c3ed5hfifavpy= 43khzg5fyjdmrnlfk3b7va/w91m22j33vxj3vvfa8lv04qjansdzr0d", O_RDONLY) =3D 13 fstat(13, {st_mode=3DS_IFREG|0600, st_size=3D105, ...}) =3D 0 lseek(13, 0, SEEK_CUR) =3D 0 read(13, "(narinfo (version 2) (cache-uri \"https://mirror.hydra.gnu.org\")= (date 1522315814) (ttl 10800) (value #f))", 4096) =3D 105 close(13) =3D 0 write(1, "\n", 1) =3D 1 --8<---------------cut here---------------end--------------->8--- To unlock it, I did: --8<---------------cut here---------------start------------->8--- $ sudo rm "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxey3= r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d" # =E2=80=A6 narinfo gets redownloaded and file gets regenerated: $ sudo cat "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxey= 3r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d" (narinfo (version 2) (cache-uri "https://berlin.guixsd.org") (date 15223164= 03) (ttl 3888000) (value "StorePath: /gnu/store/w91m22j33vxj3vvfa8lv04qjans= dzr0d-libgc-7.6.4-debug\nURL: nar/gzip/w91m22j33vxj3vvfa8lv04qjansdzr0d-lib= gc-7.6.4-debug\nCompression: gzip\nNarHash: sha256:0jrrknph5qs3n8v1prmmx4pg= ixhhdnqjh04i066c3fp12yx35hb7\nNarSize: 1462960\nReferences: 68yb572zpkn26sk= h2dp1z91w2dnmrzzb-libgc-7.6.4 6v2lw5wkb36lwcky5x4i5ris08jabihs-glibc-2.27 a= sm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib cwmia787gmr4pypna6na1nfirqlr8= y0p-gcc-5.5.0 fbclk7l7fn4qh6nwi1xl1wbszhhj6yfd-libatomic-ops-7.6.2\nFileSiz= e: 543891\nSystem: x86_64-linux\nDeriver: 9c7ilc15k8p5b84lxhgn2jy6l6xgbdpj-= libgc-7.6.4.drv\nSignature: 1;berlin.guixsd.org;KHNpZ25hdHVyZSAKIChkYXRhIAo= gIChmbGFncyByZmM2OTc5KQogIChoYXNoIHNoYTI1NiAjRTBGRUExNkQ5ODU5Mjk1QjQ4N0IwOT= c2RTVFRkIxNDUzRTdCOUVFNkJBNUFBRkY5NUFEQTg1REY5QUJENkI4QSMpCiAgKQogKHNpZy12Y= WwgCiAgKGVjZHNhIAogICAociAjMDY0MkZCQUYwRDExNDM2NTc3NUY1QTI2REU3NDYyOTMyQzg5= RjhCM0U4RDg5MzQ4MzRBNTQwRDAwMEVBQTk5QiMpCiAgIChzICMwMzQ1RUFCMDM1MzBEMzRFOTE= wNzVFMzFFMUFENjM4OEI3NDAwRTQxRjRBOTExRjg0RDE0NEQ3M0QxMkVCMzY5IykKICAgKQogIC= kKIChwdWJsaWMta2V5IAogIChlY2MgCiAgIChjdXJ2ZSBFZDI1NTE5KQogICAocSAjOEQxNTZGM= jk1RDI0QjBEOUE4NkZBNTc0MUE4NDBGRjJEMjRGNjBGN0I2QzQxMzQ4MTRBRDU1NjI1OTcxQjM5= NCMpCiAgICkKICApCiApCg=3D=3D\n")) --8<---------------cut here---------------end--------------->8--- =E2=80=A6 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(storePath)); worker.store.querySubstitutablePathInfos(sub, dummy, infos); SubstitutablePathInfos::iterator k =3D infos.find(storePath); if (k =3D=3D infos.end()) { tryNext(); return; } info =3D k->second; hasSubstitute =3D true; Ludo=E2=80=99.