bug#72722: [cuirass] Failure to write build log leads to build failure

bug#72722: [cuirass] Failure to write build log leads to build failure

[Ludovic Courtès]

We occasionally see failed builds with truncated logs on ci.guix.  These
happens in situations where ‘cuirass remote-worker’ gets EPIPE as it
sends the build log to ‘remote-server’:

--8<---------------cut here---------------start------------->8---
2024-08-19 19:54:52 @ substituter-started /gnu/store/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv substitute
2024-08-19 19:54:52 Downloading http://141.80.167.131/nar/lzip/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv...
2024-08-19 19:54:52 
2024-08-19 19:54:52 ESC[K libomp-16.0.6.drv                            1.8MiB/s 00:00 | 1KiB transferred
2024-08-19 19:54:52 ESC[K libomp-16.0.6.drv                            942KiB/s 00:00 | 1KiB transferred
2024-08-19 19:54:52 
2024-08-19 19:54:52 @ substituter-succeeded /gnu/store/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv
2024-08-19 19:55:04 warning: zlib error in 'gzwrite' while sending log to 141.80.167.131: 0
2024-08-19 19:55:04 error: gdPO1dI1: unexpected error while building '/gnu/store/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv': #<&compound-exception components: (#<&external-error> #<&origin origin: "fport_write"> #<&message message: "~A"> #<&irritants irritants: ("Broken pipe")> #<&exception-with-kind-and-args kind: system-error args: ("fport_write" "~A" ("Broken pipe") (32))>)>
--8<---------------cut here---------------end--------------->8---

The “unexpected error while building” message was added in
ba3ea7947ec67e9d9585e40a30d67dbd8115e73c.

This suggests that the ‘catch #t’ around the ‘send-log’ call doesn’t
have the desired effect; instead, the ‘guard’ handler is invoked.

It looks like EPIPE comes from the pipe set up by ‘build-derivations&’
and that the underlying ‘build-derivations’ call keeps writing to even
after ‘send-log’ has closed it.

Ludo’.

bug#72722: [cuirass] Failure to write build log leads to build failure

[Ludovic Courtès]

Hi,

Ludovic Courtès <ludovic.courtes@inria.fr> skribis:

> We occasionally see failed builds with truncated logs on ci.guix.  These
> happens in situations where ‘cuirass remote-worker’ gets EPIPE as it
> sends the build log to ‘remote-server’:
>
> 2024-08-19 19:54:52 @ substituter-started /gnu/store/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv substitute
> 2024-08-19 19:54:52 Downloading http://141.80.167.131/nar/lzip/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv...
> 2024-08-19 19:54:52 
> 2024-08-19 19:54:52 ESC[K libomp-16.0.6.drv                            1.8MiB/s 00:00 | 1KiB transferred
> 2024-08-19 19:54:52 ESC[K libomp-16.0.6.drv                            942KiB/s 00:00 | 1KiB transferred
> 2024-08-19 19:54:52 
> 2024-08-19 19:54:52 @ substituter-succeeded /gnu/store/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv
> 2024-08-19 19:55:04 warning: zlib error in 'gzwrite' while sending log to 141.80.167.131: 0
> 2024-08-19 19:55:04 error: gdPO1dI1: unexpected error while building '/gnu/store/sv3z77cgg2788hrl87w35bfmyhkmkv54-libomp-16.0.6.drv': #<&compound-exception components: (#<&external-error> #<&origin origin: "fport_write"> #<&message message: "~A"> #<&irritants irritants: ("Broken pipe")> #<&exception-with-kind-and-args kind: system-error args: ("fport_write" "~A" ("Broken pipe") (32))>)>

But hey, why does ‘gzwrite’ fail in the first place?

I noticed that this usually happened when dumping big logs (several
MiBs) very quickly (typically the unpack phase of a large package like
LLVM producing lots of data very quickly.)

As it turns out, ‘send-log’ opens its socket with SOCK_NONBLOCK, and
then passes it to zlib, which writes to it in ‘gzwrite’.  But zlib is
not equipped to deal with EAGAIN: it just errors out, with ‘gzwrite’
returning Z_ERRNO, hence the bug above.

I was able to confirm this hypothesis by running:

   echo '(log-server (version 0))' | nc -l -p 5000 -v | \
     (sleep 10; echo starting >&2; wc -c)

and then, from a REPL:

  scheme@(cuirass remote)> (send-log "127.0.0.1" 5000 "foo.drv" (open-input-file "llvm.log"))
  2024-08-22T16:35:37 warning: zlib error in 'gzwrite' while sending log to 127.0.0.1: -1 <fd:19>: Resource temporarily unavailable
  $30 = #f

QED.  (Here I used Guile-zlib 0.2.1 with a small modification to
‘remote.scm’ so it displays the error message after Z_ERRNO = -1.)

Ludo’.

bug#72722: [cuirass] Failure to write build log leads to build failure

[Ludovic Courtès]

Ludovic Courtès <ludo@gnu.org> skribis:

> As it turns out, ‘send-log’ opens its socket with SOCK_NONBLOCK, and
> then passes it to zlib, which writes to it in ‘gzwrite’.  But zlib is
> not equipped to deal with EAGAIN: it just errors out, with ‘gzwrite’
> returning Z_ERRNO, hence the bug above.

Fixed in 59010a5ba32a5f0802d28900908ee9c75f473a66.

Ludo’.

bug#72722: [cuirass] Failure to write build log leads to build failure

[Ludovic Courtès]

Ludovic Courtès <ludo@gnu.org> skribis:

> As it turns out, ‘send-log’ opens its socket with SOCK_NONBLOCK, and
> then passes it to zlib, which writes to it in ‘gzwrite’.  But zlib is
> not equipped to deal with EAGAIN: it just errors out, with ‘gzwrite’
> returning Z_ERRNO, hence the bug above.

Fixed in 59010a5ba32a5f0802d28900908ee9c75f473a66.

Ludo’.