bug#61839: [Cuirass] Build timeouts during evaluations

[Ludovic Courtès]

Hello Guix!

We often get evaluation errors for ‘core-updates’, where the build log
reveals that this is due to a build timeout while building the Guix
instance that will be used for the evaluation.  Example:

--8<---------------cut here---------------start------------->8---
building of `/gnu/store/x9dyzywwmsp8vmpvpx54yhcnz7rqin0l-asciidoc-9.1.0.drv' 
timed out after 3600 seconds of silence
cannot build derivation 
`/gnu/store/bl7aq8999lmp6flbyw3k656m522jmcl3-git-2.39.1.drv': 1 dependencies 
couldn't be built
cannot build derivation 
`/gnu/store/ldajjyvb4np1zq9l9s09j0dpsbpscpan-gnulib-2022-12-06-1.440b528.drv': 
1 dependencies couldn't be built
cannot build derivation 
`/gnu/store/fdks470j7xjw3dc6fiyw15hdsxj6cdbc-guile-gnutls-3.7.11.drv': 1 
dependencies couldn't be built
cannot build derivation 
`/gnu/store/71pl6a38bd0b81qgi45wz2ymvlv0x7xn-guix-cli-core.drv': 1 dependencies 
couldn't be built

[...]

cannot build derivation 
`/gnu/store/m7r73wypxhhmv8cqza1x8g2zyq9k1xpg-profile.drv': 1 dependencies 
couldn't be built

[...]

ERROR:
  1. &store-protocol-error:
      message: "build of 
`/gnu/store/m7r73wypxhhmv8cqza1x8g2zyq9k1xpg-profile.drv' failed"
      status: 101
--8<---------------cut here---------------end--------------->8---

(From <https://ci.guix.gnu.org/eval/233402/log/raw>.)

Likewise for the ‘guile’ jobset:

--8<---------------cut here---------------start------------->8---
exporting path `/gnu/store/m2hyx7qk2j1bsvpj1qv89701klv8kqkk-guix-command'
exporting path 
`/gnu/store/vlm7401d5jvna6j7qdxhcr581cd8g8vh-guix-daemon-1.4.0-4.01fd830'
exporting path `/gnu/store/zv3c0anfj085d2lyxh4g4aahhczmcaj8-guix-daemon'
exporting path `/gnu/store/f26rw4haizf2h126k9ja9wk31cm49mj0-guix-17bd02433'
exporting path `/gnu/store/wc736va72zl2zz36817ahf3kc5fkfr69-inferior-script.scm'
building of `/gnu/store/yq9r44lic8cn4nphksbi5s3ppwfcsh1n-guile.drv' timed out 
after 3600 seconds of silence
cannot build derivation 
`/gnu/store/nrcsvww8j24rjzyin90w76qgbkgphhvp-profile.drv': 1 dependencies 
couldn't be built
Backtrace:
In ice-9/boot-9.scm:
  1752:10 12 (with-exception-handler _ _ #:unwind? _ # _)
In unknown file:
          11 (apply-smob/0 #<thunk 7fd8cbe13340>)
In ice-9/boot-9.scm:
    724:2 10 (call-with-prompt _ _ #<procedure default-prompt-handle?>)
In ice-9/eval.scm:
    619:8  9 (_ #(#(#<directory (guile-user) 7fd8cbe16c80>)))
In cuirass/ui.scm:
   104:10  8 (run-cuirass-command _ . _)
In cuirass/scripts/evaluate.scm:
   105:27  7 (cuirass-evaluate _)
In ice-9/boot-9.scm:
  1752:10  6 (with-exception-handler _ _ #:unwind? _ # _)
In guix/store.scm:
   658:37  5 (thunk)
  2123:25  4 (run-with-store #<store-connection 256.99 7fd8cad09dc0> ?)
In cuirass/scripts/evaluate.scm:
     87:8  3 (_ _)
In guix/store.scm:
  1995:38  2 (_ #<store-connection 256.99 7fd8a33e6d70>)
  1421:15  1 (_ #<store-connection 256.99 7fd8a33e6d70> _ _)
In ice-9/boot-9.scm:
  1685:16  0 (raise-exception _ #:continuable? _)

ice-9/boot-9.scm:1685:16: In procedure raise-exception:
ERROR:
  1. &store-protocol-error:
      message: "build of 
`/gnu/store/nrcsvww8j24rjzyin90w76qgbkgphhvp-profile.drv' failed"
      status: 101
--8<---------------cut here---------------end--------------->8---

Building this particular derivation is quick though:

--8<---------------cut here---------------start------------->8---
$ time guix build /gnu/store/yq9r44lic8cn4nphksbi5s3ppwfcsh1n-guile.drv --check
The following derivation will be built:
  /gnu/store/yq9r44lic8cn4nphksbi5s3ppwfcsh1n-guile.drv
building /gnu/store/yq9r44lic8cn4nphksbi5s3ppwfcsh1n-guile.drv...
(repl-version 0 1 1)
(values (value 
"/gnu/store/rgk1sc2zvllf7cgbyj5g28b9v2x6nvn3-guile/share/guile/site/3.0"))
successfully built /gnu/store/yq9r44lic8cn4nphksbi5s3ppwfcsh1n-guile.drv
successfully built /gnu/store/yq9r44lic8cn4nphksbi5s3ppwfcsh1n-guile.drv
/gnu/store/rgk1sc2zvllf7cgbyj5g28b9v2x6nvn3-guile

real    0m1.253s
user    0m0.751s
sys     0m0.034s
--8<---------------cut here---------------end--------------->8---

So the problem must be elsewhere.

One thing is that this particular .drv is quite big:

--8<---------------cut here---------------start------------->8---
$ guix size /gnu/store/yq9r44lic8cn4nphksbi5s3ppwfcsh1n-guile.drv
store item                                                       total    self
/gnu/store/wjr1sqxci75jfkvwzmmvlgypkyp3fvqi-guix-17bd024           105.0   
105.0  42.9%
/gnu/store/6b3fp2kwqxw7cvnh6jz9g49n9k2n5avy-guix-packages-base-source    36.2   
 36.2  14.8%
/gnu/store/h3hjni2bd8f5kbn8w0g2xx2jnagfynnr-guile-e2ed33e           29.0    
29.0  11.8%
/gnu/store/gfb26xn5f2qyrxzv847cd6iql6h8igh0-packages                23.1    
23.1   9.4%
/gnu/store/dj8rq4jd8qgk4k1hzg8djcvi6hlbdb7m-doc                     22.3    
22.3   9.1%
/gnu/store/a5z192qxni40ly92cknwxkpnxc8zxfgf-guix                     7.8     
7.8   3.2%
/gnu/store/f8wg2y3rrh4dgi6znjrv8a1l4ymkc7rb-guix-packages-source     2.8     
2.8   1.2%
/gnu/store/8iwm8x6472xnf7g6hfxzw029gxm1qbkq-guix-system-source       2.5     
2.5   1.0%
/gnu/store/2dxbf11shgvs1cgvzz6wpnfra97f0sfw-guix-extra-source        2.5     
2.5   1.0%
/gnu/store/q57az26zdgafic5b8xsbxlh4iwddvr86-doc                      2.1     
2.1   0.9%
[…]
/gnu/store/0mxnx8l4fgigvd7gakwdk6hc6im4wnai-disarchive-mirrors       0.0     
0.0   0.0%
total: 244.8 MiB
--8<---------------cut here---------------end--------------->8---

Merely transferring it for offloading takes time; depending on machine
load, perhaps it can hit the 1h max-silent timeout?  That’d mean the
throughput is below 70 KiB/s.  Plausible?

The closure of
/gnu/store/x9dyzywwmsp8vmpvpx54yhcnz7rqin0l-asciidoc-9.1.0.drv is
3.0 MiB and it builds in 4 seconds, so there must be something else
going on, perhaps a bug in libssh/Guile-SSH leading to stale
connections?

Thoughts?

Ludo’.