bug#49781: Successful build on ci.guix not available as substitute

[Ludovic Courtès]

Hello!

Mathieu Othacehe <othacehe@gnu.org> skribis:

> Your understanding is correct :). However, looking at the
> cuirass-remote-server.log file, I found:
>
> 2021-07-29T22:31:48 fetching 
> '/gnu/store/hrn9hj7v1img3il6afh3r036aczvwnyd-xnnpack-0.0-1.bbe8824.drv' from 
> http://141.80.167.185:5558
> 2021-07-29T22:31:48 Failed to add 
> /gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824 to store.
>
>
> There are quite a few other "Failed to add" traces in the log, and they
> all seem to involve the machine behind the .185 IP address.

Ah ha!

> Fetching the substitute manually from Berlin works:
>
>  wget 
> http://141.80.167.185:5558/nar/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824
>  --no-http-keep-alive
>
>
> but using "ensure-path" fails this way:
>
> scheme@(guix-user)> (set-build-options* s "http://141.80.167.185:5558";)
> $1 = #t
> scheme@(guix-user)> (ensure-path s 
> "/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824")
> substitute: updating substitutes from 'http://141.80.167.185:5558'... 100.0%
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
> ice-9/boot-9.scm:1669:16: In procedure raise-exception:
> ERROR:
>   1. &store-protocol-error:
>       message: "path 
> `/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824' does not 
> exist and cannot be created"
>       status: 1
>
> Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
>
> Do you see any reason why ensure-path would fail while wget works?

The cache on berlin says this substitute is available from .185:

--8<---------------cut here---------------start------------->8---
ludo@berlin ~$ sudo cat 
/var/guix/substitute/cache/mlcrs6tdmrqacbxadjqt4svma66gjcemoqjydai2vxshcokzw3fa/slm0x0j05vyl3vqbjhgc0nch6jca9fp3;
 echo
(narinfo (version 2) (cache-uri "http://141.80.167.185:5558";) (date 1627639693) 
(ttl 129600) (value "StorePath: 
/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824\nURL: 
nar/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824\nCompression: 
none\nFileSize: 924872\nNarHash: 
sha256:0ym303zq7shxgrl0p797bpfr8iymdwg6gc3vq85b6ms1akmj396b\nNarSize: 
924872\nReferences: 01b4w3m6mp55y531kyi1g8shh722kwqm-gcc-7.5.0-lib 
4lgnc0s0h6zpdfbv7ccgj50ya6m6gy4j-pthreadpool-0.1-1.1787867 
dv8kki4psjqyf01y0s0vf6j5hw3sm5wk-cpuinfo-0.0-1.866ae6e 
fa6wj5bxkj5ll1d7292a70knmyl7a0cr-glibc-2.31 
slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824\nSystem: 
x86_64-linux\nDeriver: 
hrn9hj7v1img3il6afh3r036aczvwnyd-xnnpack-0.0-1.bbe8824.drv\nSignature: 
1;hydra-guix-128;KHNpZ25hdHVyZSAKIChkYXRhIAogIChmbGFncyByZmM2OTc5KQogIChoYXNoIHNoYTI1NiAjRjQzQTYyOTFERTM5QjY4MUVCRTQxNEZGRTE0NUNGQ0E5RDhEREQ5OTc3QTM0RUUzOTIxQzg3OEQ3N0JBMkFEOCMpCiAgKQogKHNpZy12YWwgCiAgKGVjZHNhIAogICAociAjMEVGNTIzNkIyNDk5QzAzQ0NBREIzODg2QUMwQUQzODg4QTUyOEU2NTQ3NTIxM0Q0ODYyNjYwMUJEODE1RDdGQyMpCiAgIChzICMwQTQ0ODU5N0VBNUJFODFFOEJFRDlDRkM2MkFFRTEwMUIxQjdGN0U1RUM5RTlFRDc1Q0Q0NjQ4NkYyQUVGNThFIykKICAgKQogICkKIChwdWJsaWMta2V5IAogIChlY2MgCiAgIChjdXJ2ZSBFZDI1NTE5KQogICAocSAjRkQyMEI1QjVFMDkwQjVBMzYzMTI0OTA1RTJDQjAyMEZCOUIzQzk3QTU0NTUxMDI4REYwQTM2NEU0QzRDNjY1MyMpCiAgICkKICApCiApCg==\n"))
--8<---------------cut here---------------end--------------->8---

Yet, I’m also stumbling upon the ‘ensure-path’ failure above, but now
the substitute seems to have vanished:

--8<---------------cut here---------------start------------->8---
scheme@(guix-user)> ,use(guix store)
scheme@(guix-user)> (define s (open-connection ))
scheme@(guix-user)> (set-build-options s #:substitute-urls 
'("http://141.80.167.185:5558";))
$1 = #t
scheme@(guix-user)> (ensure-path s 
"/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824")
substitute: updating substitutes from 'http://141.80.167.185:5558'... 100.0%
ice-9/boot-9.scm:1685:16: In procedure raise-exception:
ERROR:
  1. &store-protocol-error:
      message: "path 
`/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824' does not 
exist and cannot be created"
      status: 1

Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
scheme@(guix-user) [1]> ,q
scheme@(guix-user)> (substitutable-path-info s 
'("/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824"))
substitute: updating substitutes from 'http://141.80.167.185:5558'... 100.0%
$2 = ()
scheme@(guix-user)> 
[1]+  Stopped                 guix repl
ludo@berlin ~$ sudo cat 
/var/guix/substitute/cache/mlcrs6tdmrqacbxadjqt4svma66gjcemoqjydai2vxshcokzw3fa/slm0x0j05vyl3vqbjhgc0nch6jca9fp3;
 echo (narinfo (version 2) (cache-uri "http://141.80.167.185:5558";) (date 
1627892782) (ttl 0) (value #f))
ludo@berlin ~$ fg
guix repl

scheme@(guix-user)> (substitutable-path-info s 
'("/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824"))
substitute: updating substitutes from 'http://141.80.167.185:5558'... 100.0%
$3 = ()
scheme@(guix-user)> (substitutable-path-info s 
'("/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824"))
substitute: updating substitutes from 'http://141.80.167.185:5558'... 100.0%
$4 = ()
scheme@(guix-user)> ,q
ludo@berlin ~$ wget -O - 
http://141.80.167.185:5558/slm0x0j05vyl3vqbjhgc0nch6jca9fp3.narinfo
--2021-08-02 10:28:22--  
http://141.80.167.185:5558/slm0x0j05vyl3vqbjhgc0nch6jca9fp3.narinfo
Connecting to 141.80.167.185:5558... connected.
HTTP request sent, awaiting response... 404 Not Found
2021-08-02 10:28:22 ERROR 404: Not Found.
--8<---------------cut here---------------end--------------->8---

And indeed, the store item no longer is on .185:

--8<---------------cut here---------------start------------->8---
ludo@berlin ~$ sudo ssh hydra@141.80.167.185
-bash-5.0$ ls /gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824
ls: cannot access 
'/gnu/store/slm0x0j05vyl3vqbjhgc0nch6jca9fp3-xnnpack-0.0-1.bbe8824': No such 
file or directory
--8<---------------cut here---------------end--------------->8---

One of the problems is that .185 did not advertise a TTL on its
narinfos, hence the default of (* 36 3600) = 129600 that we saw above.
That in turn explains some discrepancies: ‘guix substitute’ thinks the
nar is still around but the corresponding /nar request fails because it
has disappeared in the meantime.

But perhaps the core issue is that .185 did not keep the build result
long enough, perhaps because GC ran right after the build?  Is that
plausible?

Thanks,
Ludo’.