GNU logs - #30986, boring messages


Message sent to bug-guix@HIDDEN:


X-Loop: help-debbugs@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
X-GNU-PR-Message: report 30986
X-GNU-PR-Package: guix
X-GNU-PR-Keywords: 
To: 30986 <at> debbugs.gnu.org
X-Debbugs-Original-To: bug-guix@HIDDEN
Received: via spool by submit <at> debbugs.gnu.org id=B.152233674018615
          (code B ref -1); Thu, 29 Mar 2018 15:19:02 +0000
Received: (at submit) by debbugs.gnu.org; 29 Mar 2018 15:19:00 +0000
Received: from localhost ([127.0.0.1]:58822 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1f1ZKO-0004qA-Bm
	for submit <at> debbugs.gnu.org; Thu, 29 Mar 2018 11:19:00 -0400
Received: from eggs.gnu.org ([208.118.235.92]:34805)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <ludo@HIDDEN>) id 1f1ZKM-0004px-7x
 for submit <at> debbugs.gnu.org; Thu, 29 Mar 2018 11:18:58 -0400
Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71)
 (envelope-from <ludo@HIDDEN>) id 1f1ZKF-0006VK-8x
 for submit <at> debbugs.gnu.org; Thu, 29 Mar 2018 11:18:52 -0400
X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on eggs.gnu.org
X-Spam-Level: 
X-Spam-Status: No, score=0.8 required=5.0 tests=BAYES_50,T_RP_MATCHES_RCVD,
 WEIRD_QUOTING autolearn=disabled version=3.3.2
Received: from lists.gnu.org ([2001:4830:134:3::11]:47939)
 by eggs.gnu.org with esmtps (TLS1.0:RSA_AES_256_CBC_SHA1:32)
 (Exim 4.71) (envelope-from <ludo@HIDDEN>) id 1f1ZKF-0006Ur-5C
 for submit <at> debbugs.gnu.org; Thu, 29 Mar 2018 11:18:51 -0400
Received: from eggs.gnu.org ([2001:4830:134:3::10]:54003)
 by lists.gnu.org with esmtp (Exim 4.71)
 (envelope-from <ludo@HIDDEN>) id 1f1ZKC-0008JN-PT
 for bug-guix@HIDDEN; Thu, 29 Mar 2018 11:18:50 -0400
Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71)
 (envelope-from <ludo@HIDDEN>) id 1f1ZK8-0006Nr-Nz
 for bug-guix@HIDDEN; 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 <ludo@HIDDEN>) id 1f1ZK8-0006Lw-DH
 for bug-guix@HIDDEN; 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 <bug-guix@HIDDEN>; Thu, 29 Mar 2018 17:18:42 +0200 (CEST)
X-Virus-Scanned: Debian amavisd-new at aquilenet.fr
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 <bug-guix@HIDDEN>;
 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 <bug-guix@HIDDEN>; Thu, 29 Mar 2018 17:18:41 +0200 (CEST)
From: ludo@HIDDEN (Ludovic =?UTF-8?Q?Court=C3=A8s?=)
X-URL: http://www.fdn.fr/~lcourtes/
X-Revolutionary-Date: 9 Germinal an 226 de la =?UTF-8?Q?R=C3=A9volution?=
X-PGP-Key-ID: 0x090B11993D9AEBB5
X-PGP-Key: http://www.fdn.fr/~lcourtes/ludovic.asc
X-PGP-Fingerprint: 3CE4 6455 8A84 FDC6 9DB4  0CFB 090B 1199 3D9A EBB5
X-OS: x86_64-pc-linux-gnu
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
X-detected-operating-system: by eggs.gnu.org: Genre and OS details not
 recognized.
X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.6.x
X-Received-From: 2001:4830:134:3::11
X-Spam-Score: -5.0 (-----)
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -5.0 (-----)

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


Message sent to bug-guix@HIDDEN:


X-Loop: help-debbugs@HIDDEN
Subject: bug#30986: =?UTF-8?Q?=E2=80=98guix_?= =?UTF-8?Q?substitute=E2=80=99?= spins forever
Resent-From: Simon Tournier <zimon.toutoune@HIDDEN>
Original-Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
Resent-CC: bug-guix@HIDDEN
Resent-Date: Mon, 16 Jun 2025 11:50:03 +0000
Resent-Message-ID: <handler.30986.B30986.175007459631481 <at> debbugs.gnu.org>
Resent-Sender: help-debbugs@HIDDEN
X-GNU-PR-Message: followup 30986
X-GNU-PR-Package: guix
X-GNU-PR-Keywords: 
To: ludo@HIDDEN (Ludovic =?UTF-8?Q?Court=C3=A8s?=)
Cc: 30986 <at> debbugs.gnu.org
Received: via spool by 30986-submit <at> debbugs.gnu.org id=B30986.175007459631481
          (code B ref 30986); Mon, 16 Jun 2025 11:50:03 +0000
Received: (at 30986) by debbugs.gnu.org; 16 Jun 2025 11:49:56 +0000
Received: from localhost ([127.0.0.1]:43607 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1uR8LY-0008B6-Oa
	for submit <at> debbugs.gnu.org; Mon, 16 Jun 2025 07:49:55 -0400
Received: from mail-wm1-x333.google.com ([2a00:1450:4864:20::333]:44164)
 by debbugs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128)
 (Exim 4.84_2) (envelope-from <zimon.toutoune@HIDDEN>)
 id 1uR8LL-00088O-Pz
 for 30986 <at> debbugs.gnu.org; Mon, 16 Jun 2025 07:49:43 -0400
Received: by mail-wm1-x333.google.com with SMTP id
 5b1f17b1804b1-4530921461aso36848435e9.0
 for <30986 <at> debbugs.gnu.org>; Mon, 16 Jun 2025 04:49:39 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
 d=gmail.com; s=20230601; t=1750074573; x=1750679373; darn=debbugs.gnu.org;
 h=content-transfer-encoding:mime-version:user-agent:message-id:date
 :references:in-reply-to:subject:cc:to:from:from:to:cc:subject:date
 :message-id:reply-to;
 bh=VFUyp53n6+dIFg4AfDvJ9XU0aiujURc7Tya7cqR1+WQ=;
 b=BB2a+1qx4E0wvd5RGBNKPRLfkEOcbfzJEDugYv/0spOGYG3+i4QpCwqzHMA1yACJST
 HfPo3iXiZHosjtSJBIo10dhyUiZI/aNbLUV2Qijkk3JO1y6gqF433pqtWXn4bZI0JCBH
 svdiQgVJCFdUb5Vh3JXJ3ygE3bSXyGfCS5jn2YJizPJDEZhR3pjVceef3+ZqXRw7kYPm
 JGnbCQ7t9RAEt07GfguTIBK4KDU+1hdqshTaomoITzF892EVsSaUlPbWoValQ1xA0Dwp
 15oiEoilq3U+s+V5j0FNsD9mHFBFhbI/RVGYlkikv9dhLHOfmwDuw42ofEl5cqhNx+ru
 wz8A==
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
 d=1e100.net; s=20230601; t=1750074573; x=1750679373;
 h=content-transfer-encoding:mime-version:user-agent:message-id:date
 :references:in-reply-to:subject:cc:to:from:x-gm-message-state:from
 :to:cc:subject:date:message-id:reply-to;
 bh=VFUyp53n6+dIFg4AfDvJ9XU0aiujURc7Tya7cqR1+WQ=;
 b=FTCbomhe5yQ+dVMRWyCHE3yD5gNo8pH9Sjwzth0Btdo45ZZmgF9IJikXYbekGDunsz
 fvv461BFxSllp9lhNZoZFa7Gm18pdVaGMatcC/NWHNR3LYgAjH7vQ+mqfy66LhRlvAyo
 +BxPoP6/IhKrZMl6rhZBIPj15so6qOzknxz1y8YtAEizF0Gl7ylmHSlWMpaGykVVQh5H
 qVAihxMXMFL6eMPXvkUJPqgwGCQBEkl3zD4v5tSjPum8wGY45FZ8JRa/1EYopFovziV0
 s1yxp17jWdO0v499GiBTN+AKWrvjMzTOh9Xv7Hv80aMStuC2Rpi7ijfLjghQ3lJi75nN
 oAHg==
X-Gm-Message-State: AOJu0Yx6pZJ7eSpBCs/S3w4me9yETIupn/oZ5sOAMnApwKcS21ZxOIlt
 VQA0i5qGrEZ28yPOjHK8AqFr5djjDAbiB4LXSnu+y2uriR7+q7GAAFQCDyO0/40d
X-Gm-Gg: ASbGncvgHh85NRJBEna6LrWSvNfvoKxDlpa4UpxIYuBPuiNfVeGl0ynFrNW6GmAxTlm
 6IS3gwPofW1rhyw4fTDwtirw9zg+/ITV8uAkAkJdO7BShJBznUhK5SPNoFEEJbZcmFA0/oa5JFY
 SW3LRf32ln+rXV1VSeIFj4WejG0n6S5VMLXPlOn2hCdlynXPecgZW5nCLqTZ1F11y4jRyPJky1w
 q5sBEDzqwQxnPDLOM8qwhxhnCa9PtT2v11ThHxsJskVaKYIqxRnZsbtwdqzpTfE3kmZb/bm6nw4
 xCwu4FHtUWmTwexdJu3uqxgS7rOnm9rMJSEPOiTyXkFr1/9XTtbrZoHuYTxdEH+ThjDA1gUVgQ8
 8GEyu9fx16XrgeesOCRX1EXw=
X-Google-Smtp-Source: AGHT+IES2wua2NN/ZOUNmnUkPdRt1EpE7Dr5oQOAMgphmm0yf+z969Qjtg63L9y1bSYW4zFrJcuAQA==
X-Received: by 2002:a05:600c:4ed1:b0:453:78f:fa9f with SMTP id
 5b1f17b1804b1-4533ca510afmr80532635e9.11.1750074573303; 
 Mon, 16 Jun 2025 04:49:33 -0700 (PDT)
Received: from lili (nat-dsi-209.net.univ-paris-diderot.fr. [81.194.30.209])
 by smtp.gmail.com with ESMTPSA id
 5b1f17b1804b1-4532e256d95sm141420535e9.31.2025.06.16.04.49.32
 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);
 Mon, 16 Jun 2025 04:49:33 -0700 (PDT)
From: Simon Tournier <zimon.toutoune@HIDDEN>
In-Reply-To: <87po3mvrjj.fsf@HIDDEN> ("Ludovic =?UTF-8?Q?Court=C3=A8s?="'s message of "Thu, 29 Mar 2018 17:18:40 +0200")
References: <87po3mvrjj.fsf@HIDDEN>
Date: Mon, 16 Jun 2025 12:05:37 +0200
Message-ID: <87ldps80i6.fsf@HIDDEN>
User-Agent: Gnus/5.13 (Gnus v5.13)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
X-Spam-Score: 0.0 (/)
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -1.0 (-)

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, ludo@HIDDEN (Ludovic Court=C3=A8s) wrote:

> 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 t=
hat the
> following two =E2=80=9Cinfo=E2=80=9D queries would happen in a loop:
>
> read(0, "info /gnu/store/cwmia787gmr4pypna6na1nfirqlr8y0p-gcc-5.5.0 \n", =
4096) =3D 60
> openat(AT_FDCWD, "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn=
3hwbhxey3r7suq2a65qr2ulq/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\") =
(date 1522315393) (ttl 3888000) (value \"StorePath: /gnu/store/cwmia787gmr4=
pypna6na1nfirqlr8y0p-gcc-5.5.0\\nURL: nar/gzip/cwmia787gmr4pypna6na1nfirqlr=
8y0p-gcc-5.5.0\\nCompression: gzip\\nNarHash: sha256:039i94jrmfsvn859kjarcm=
qzabs3nspmbz912gy03p0v6n64dr56\\nNarSize: 98156824\\nReferences: 03j2yq30pc=
d2h17np0liarb2jdijg8y4-bash-static-4.4.19 6v2lw5wkb36lwcky5x4i5ris08jabihs-=
glibc-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", 5=
8) =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", 5=
8) =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/bzh2rehitrzflwj2f3tcyt25s7xn=
3hwbhxey3r7suq2a65qr2ulq/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\") =
(date 1522315402) (ttl 300) (value #f))", 4096) =3D 100
> close(13)                               =3D 0
> openat(AT_FDCWD, "/var/guix/substitute/cache/s3o7shxygzvof4rs6c3ed5hfifav=
py43khzg5fyjdmrnlfk3b7va/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
>
>
> 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-c=
onfig-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.o=
rg'... 100.0%
> @ substituter-started /gnu/store/68yb572zpkn26skh2dp1z91w2dnmrzzb-libgc-7=
.6.4 /gnu/store/fbpk1zjcqd6p4ny8qx48mvlp4v7qfmld-guix-0.14.0-9.bdf0c64/libe=
xec/guix/substitute
> Downloading https://berlin.guixsd.org/nar/gzip/68yb572zpkn26skh2dp1z91w2d=
nmrzzb-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%
>
> [=E2=80=A6 hangs here=E2=80=A6]
>
>
> While it=E2=80=99s hanging, =E2=80=98guix substitute=E2=80=99 receives th=
is one query in a loop:
>
> read(0, "info /gnu/store/w91m22j33vxj3vvfa8lv04qjansdzr0d-libgc-7.6.4-deb=
ug \n", 4096) =3D 68
> openat(AT_FDCWD, "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn=
3hwbhxey3r7suq2a65qr2ulq/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\") =
(date 1522315814) (ttl 300) (value #f))", 4096) =3D 100
> close(13)                               =3D 0
> openat(AT_FDCWD, "/var/guix/substitute/cache/s3o7shxygzvof4rs6c3ed5hfifav=
py43khzg5fyjdmrnlfk3b7va/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
>
>
> To unlock it, I did:
>
> $ sudo rm "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhxe=
y3r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d"
> # =E2=80=A6 narinfo gets redownloaded and file gets regenerated:
> $ sudo cat "/var/guix/substitute/cache/bzh2rehitrzflwj2f3tcyt25s7xn3hwbhx=
ey3r7suq2a65qr2ulq/w91m22j33vxj3vvfa8lv04qjansdzr0d"
> (narinfo (version 2) (cache-uri "https://berlin.guixsd.org") (date 152231=
6403) (ttl 3888000) (value "StorePath: /gnu/store/w91m22j33vxj3vvfa8lv04qja=
nsdzr0d-libgc-7.6.4-debug\nURL: nar/gzip/w91m22j33vxj3vvfa8lv04qjansdzr0d-l=
ibgc-7.6.4-debug\nCompression: gzip\nNarHash: sha256:0jrrknph5qs3n8v1prmmx4=
pgixhhdnqjh04i066c3fp12yx35hb7\nNarSize: 1462960\nReferences: 68yb572zpkn26=
skh2dp1z91w2dnmrzzb-libgc-7.6.4 6v2lw5wkb36lwcky5x4i5ris08jabihs-glibc-2.27=
 asm7j8dm594ljjvs0x90h8qivl5qdaz8-gcc-5.5.0-lib cwmia787gmr4pypna6na1nfirql=
r8y0p-gcc-5.5.0 fbclk7l7fn4qh6nwi1xl1wbszhhj6yfd-libatomic-ops-7.6.2\nFileS=
ize: 543891\nSystem: x86_64-linux\nDeriver: 9c7ilc15k8p5b84lxhgn2jy6l6xgbdp=
j-libgc-7.6.4.drv\nSignature: 1;berlin.guixsd.org;KHNpZ25hdHVyZSAKIChkYXRhI=
AogIChmbGFncyByZmM2OTc5KQogIChoYXNoIHNoYTI1NiAjRTBGRUExNkQ5ODU5Mjk1QjQ4N0Iw=
OTc2RTVFRkIxNDUzRTdCOUVFNkJBNUFBRkY5NUFEQTg1REY5QUJENkI4QSMpCiAgKQogKHNpZy1=
2YWwgCiAgKGVjZHNhIAogICAociAjMDY0MkZCQUYwRDExNDM2NTc3NUY1QTI2REU3NDYyOTMyQz=
g5RjhCM0U4RDg5MzQ4MzRBNTQwRDAwMEVBQTk5QiMpCiAgIChzICMwMzQ1RUFCMDM1MzBEMzRFO=
TEwNzVFMzFFMUFENjM4OEI3NDAwRTQxRjRBOTExRjg0RDE0NEQ3M0QxMkVCMzY5IykKICAgKQog=
ICkKIChwdWJsaWMta2V5IAogIChlY2MgCiAgIChjdXJ2ZSBFZDI1NTE5KQogICAocSAjOEQxNTZ=
GMjk1RDI0QjBEOUE4NkZBNTc0MUE4NDBGRjJEMjRGNjBGN0I2QzQxMzQ4MTRBRDU1NjI1OTcxQj=
M5NCMpCiAgICkKICApCiApCg=3D=3D\n"))
>
> =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;

BTW, if it appears to you unrelated, what is the status of this old bug
with only one message? :-)

Cheers,
simon





Last modified: Mon, 16 Jun 2025 12:00:02 UTC

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