GNU logs - #30986, boring messages

Message sent to bug-guix@HIDDEN:

Subject: bug#30986: =?UTF-8?Q?=E2=80=98guix_?= =?UTF-8?Q?substitute=E2=80=99?= spins forever
Resent-From: ludo@HIDDEN (Ludovic =?UTF-8?Q?Court=C3=A8s?=)
Original-Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
Resent-CC: bug-guix@HIDDEN
Resent-Date: Thu, 29 Mar 2018 15:19:02 +0000
Resent-Message-ID: <handler.30986.B.152233674018615 <at> debbugs.gnu.org>
Resent-Sender: help-debbugs@HIDDEN
To: 30986 <at> debbugs.gnu.org
From: ludo@HIDDEN (Ludovic =?UTF-8?Q?Court=C3=A8s?=)
Date: Thu, 29 Mar 2018 17:18:40 +0200
Message-ID: <87po3mvrjj.fsf@HIDDEN>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/25.3 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
Precedence: list
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> 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<PathSet>(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.

Message sent:

Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-Mailer: MIME-tools 5.505 (Entity 5.505)
Content-Type: text/plain; charset=utf-8
X-Loop: help-debbugs@HIDDEN
From: help-debbugs@HIDDEN (GNU bug Tracking System)
To: ludo@HIDDEN (Ludovic =?UTF-8?Q?Court=C3=A8s?=)
Subject: bug#30986: Acknowledgement (=?UTF-8?Q?=E2=80=98guix_?=
 =?UTF-8?Q?substitute=E2=80=99?= spins forever)
Message-ID: <handler.30986.B.152233674018615.ack <at> debbugs.gnu.org>
References: <87po3mvrjj.fsf@HIDDEN>
X-Gnu-PR-Message: ack 30986
X-Gnu-PR-Package: guix
Reply-To: 30986 <at> debbugs.gnu.org
Date: Thu, 29 Mar 2018 15:19:02 +0000

Thank you for filing a new bug report with debbugs.gnu.org.

This is an automatically generated reply to let you know your message
has been received.

Your message is being forwarded to the package maintainers and other
interested parties for their attention; they will reply in due course.

Your message has been sent to the package maintainer(s):
 bug-guix@HIDDEN

If you wish to submit further information on this problem, please
send it to 30986 <at> debbugs.gnu.org.

Please do not send mail to help-debbugs@HIDDEN unless you wish
to report a problem with the Bug-tracking system.

--=20
30986: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=3D30986
GNU Bug Tracking System
Contact help-debbugs@HIDDEN with problems

Last modified: Mon, 25 Nov 2019 12:00:02 UTC

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997 nCipher Corporation Ltd, 1994-97 Ian Jackson.