bug#26976: On Hydra, offload crashes while trying to build linux-libre source

[ludo@gnu.org (Ludovic Courtès)]

Hi again,

ludo@gnu.org (Ludovic Courtès) skribis:

> (Cc: Artyom.  Artyom, this is about what looks like a bug in Guile-SSH
> when used with Guile 2.2; see <https://bugs.gnu.org/26976>.)
>
> Mark H Weaver <mhw@netris.org> skribis:
>
>> *** Error in `/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/bin/guile': realloc(): invalid next size: 0x00000000024617d0 ***
>> ======= Backtrace: =========
>> /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(+0x70fd5)[0x7f77e8343fd5]
>> /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(+0x773a6)[0x7f77e834a3a6]
>> /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(+0x7a3a9)[0x7f77e834d3a9]
>> /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(realloc+0x156)[0x7f77e834e6e6]
>> /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0xdc6b)[0x7f77e2e24c6b]
>> /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0xddce)[0x7f77e2e24dce]
>> /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0xe50a)[0x7f77e2e2550a]
>> /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0xe7b2)[0x7f77e2e257b2]
>> /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(ssh_channel_close+0x47)[0x7f77e2e27f87]
>> /gnu/store/avy681pwf979kbwiv9k75c5h7jdink2c-guile2.2-ssh-0.11.0/lib/libguile-ssh.so.11(+0xa597)[0x7f77e3290597]
>> /gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1(+0x83785)[0x7f77e9f00785]
>
> This looks like a double-free and ‘ssh_channel_close’ has only one call
> site, which is ‘ptob_close’, the ‘close’ function for the channel port
> type in Guile-SSH.
>
> I’m quite confident that the attached patch fixes the problem.  However,
> I haven’t found a scenario in Guile 2.2 where the ‘close’ method could
> be called more than once, and I cannot reproduce the bug on my machine.
> Thoughts?
>
> I suggest applying it to the ‘guile-ssh’ package in Guix.

I went ahead and did that, in an attempt to salvage our build farm:

  https://git.savannah.gnu.org/cgit/guix.git/commit/?id=e7fbd49132406bb9ec12141ac77ac401f58ee267

The patch clearly fixes potential issues (at least use-after-free) so it
seemed appropriate to apply it anyway.

I’ve deployed Guix built against this patched Guile-SSH on
hydra.gnu.org.  I tried offloading the linux-libre build that you
mentioned, Mark, and that no longer crashed right away.  I’ve restarted
the queue-runner and I’m now monitoring the first few builds to see how
it goes:

  https://hydra.gnu.org/build/2061641
  https://hydra.gnu.org/build/2057119
  https://hydra.gnu.org/build/2054610 <- segfaulted as before
  https://hydra.gnu.org/build/2054463
  https://hydra.gnu.org/build/2053984
  https://hydra.gnu.org/build/2053974
  https://hydra.gnu.org/build/2054324

#2054610 segfaulted early on:

--8<---------------cut here---------------start------------->8---
process 1808 acquired build slot '/var/guix/offload/hydra.gnunet.org/1'
load on machine 'hydra.gnunet.org' is 0.23 (normalized: 0.115)
process 1808 acquired build slot '/var/guix/offload/guix.sjd.se/0'
load on machine 'guix.sjd.se' is 0.01 (normalized: 0.005)
sending 4 store items to 'guix.sjd.se'...
exporting path `/gnu/store/gi7r1v65zqhh8riqprq8nchfc9v9k156-guix-current'
unknown Nix trace message: @ hook-failed /gnu/store/7d688059y8j4hif7hkjs1cifqcnklw1k-guix-0.12.0-11.ce92d26+.drv - 11 builder for `/gnu/store/7d688059y8j4hif7hkjs1cifqcnklw1k-guix-0.12.0-11.ce92d26+.drv' failed due to signal 11 (Segmentation fault)
--8<---------------cut here---------------end--------------->8---

I managed to reproduce it and to get a backtrace:

--8<---------------cut here---------------start------------->8---
@ build-started /gnu/store/7d688059y8j4hif7hkjs1cifqcnklw1k-guix-0.12.0-11.ce92d26+.drv - i686-linux /var/log/guix/drvs/7d//688059y8j4hif7hkjs1cifqcnklw1k-guix-0.12.0-11.ce92d26+.drv
sending 4 store items to 'guix.sjd.se'...
exporting path `/gnu/store/gi7r1v65zqhh8riqprq8nchfc9v9k156-guix-current'
*** Error in `/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/bin/guile': realloc(): invalid next size: 0x0000000001c7c020 ***
======= Backtrace: =========
/gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(+0x70fd5)[0x7f6f8336afd5]
/gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(+0x773a6)[0x7f6f833713a6]
/gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(+0x7a3a9)[0x7f6f833743a9]
/gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6(realloc+0x156)[0x7f6f833756e6]
/gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0xdc6b)[0x7f6f7de4bc6b]
/gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0xdd7d)[0x7f6f7de4bd7d]
/gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0x39793)[0x7f6f7de77793]
/gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0x1eea7)[0x7f6f7de5cea7]
/gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4(+0xf598)[0x7f6f7de4d598]
/gnu/store/ql5h9hxh5560d42xdirh0yxzrgii6i0m-guile-ssh-0.11.0/lib/libguile-ssh.so.11(+0xa5ee)[0x7f6f7e2b75ee]
/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1(+0x8672c)[0x7f6f84f2a72c]
/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1(scm_put_bytevector+0x94)[0x7f6f84f31de4]
/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1(+0xc2c4d)[0x7f6f84f66c4d]
/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1(scm_call_n+0x16a)[0x7f6f84f6a2aa]
/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1(scm_primitive_eval+0x27)[0x7f6f84eee8d7]
/gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1(scm_primitive_load+0xdb)[0x7f6f84f0a6eb]
--8<---------------cut here---------------end--------------->8---

Cleaner backtrace from the core dumped:

--8<---------------cut here---------------start------------->8---
(gdb) bt
#0  0x00007f6f8332d2c4 in raise () from /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6
#1  0x00007f6f8332e72a in abort () from /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6
#2  0x00007f6f8336afda in __libc_message () from /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6
#3  0x00007f6f833713a6 in malloc_printerr () from /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6
#4  0x00007f6f833743a9 in _int_realloc () from /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6
#5  0x00007f6f833756e6 in realloc () from /gnu/store/rmjlycdgiq8pfy5hfi42qhw3k7p6kdav-glibc-2.25/lib/libc.so.6
#6  0x00007f6f7de4bc6b in realloc_buffer () from /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4
#7  0x00007f6f7de4bd7d in ssh_buffer_reinit () from /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4
#8  0x00007f6f7de77793 in compress_buffer () from /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4
#9  0x00007f6f7de5cea7 in packet_send2 () from /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4
#10 0x00007f6f7de4d598 in channel_write_common () from /gnu/store/vlc43y485v80sgq7iw60hzy4pw5r52d2-libssh-0.7.4/lib/libssh.so.4
#11 0x00007f6f7e2b75ee in write_to_channel_port () from /gnu/store/ql5h9hxh5560d42xdirh0yxzrgii6i0m-guile-ssh-0.11.0/lib/libguile-ssh.so.11
#12 0x00007f6f84f2a72c in scm_i_write_bytes () from /gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1
#13 0x00007f6f84f31de4 in scm_put_bytevector () from /gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1
#14 0x00007f6f84f66c4d in vm_regular_engine () from /gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1
#15 0x00007f6f84f6a2aa in scm_call_n () from /gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1
#16 0x00007f6f84eee8d7 in scm_primitive_eval () from /gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1
#17 0x00007f6f84f0a6eb in scm_primitive_load () from /gnu/store/5zx29y44nrqj0s8h3jlvlj82k8hj4dxs-guile-2.2.2/lib/libguile-2.2.so.1
--8<---------------cut here---------------end--------------->8---

<https://hydra.gnu.org/build/2066209> failed with:

--8<---------------cut here---------------start------------->8---
sending 5 store items to 'hydra-slave2.netris.org'...
exporting path `/gnu/store/yfks7lndwf36arp3xwah5dc07qwk749c-kwidgetsaddons-5.34.0-guile-builder'
exporting path `/gnu/store/zhvvhgdyakxbav26l33zg00x3byns22l-kwidgetsaddons-5.34.0.tar.xz.drv'
exporting path `/gnu/store/kn0hzhnic5qd7aqipyn9firg3nhx2m1n-kwidgetsaddons-5.34.0.drv'
exporting path `/gnu/store/mkvvbawa78dkfdyajlipas41fr5nn0hd-kwidgetsaddons-5.34.0.tar.xz'
Backtrace:
          11 (primitive-load "/gnu/store/ys7ghld9ql7knl11mpb3b072nvy?")
In guix/ui.scm:
   1264:8 10 (run-guix-command _ . _)
In guix/scripts/offload.scm:
   650:22  9 (guix-offload . _)
In ice-9/boot-9.scm:
    837:9  8 (catch _ _ #<procedure 7f27d6ab5930 at guix/ui.scm:449?> ?)
    837:9  7 (catch _ _ #<procedure 7f27d6ab5948 at guix/ui.scm:510?> ?)
In guix/scripts/offload.scm:
    340:4  6 (transfer-and-offload #<derivation /gnu/store/kn0hzhni?> ?)
In guix/ssh.scm:
    221:4  5 (send-files _ _ _ #:recursive? _ #:log-port _)
In guix/store.scm:
  1193:12  4 (export-paths #<build-daemon 256.97 199e340> _ #<outpu?> ?)
  1173:22  3 (export-path #<build-daemon 256.97 199e340> _ #<output?> ?)
   580:13  2 (process-stderr _ _)
   543:10  1 (dump-port #<input-output: socket 18> #<output: channe?> ?)
In unknown file:
           0 (put-bytevector #<output: channel (closed) 15f9a20> # 0 #)

ERROR: In procedure put-bytevector:
ERROR: Throw to key `guile-ssh-error' with args `("write_to_channel_port" "Socket error: Invalid argument" #<output: channel (closed) 15f9a20> #f)'.
--8<---------------cut here---------------end--------------->8---

… which could be a related problem (it’s the same backtrace).

I’ve stopped the queue-runner while investigating.  To be continued…

Ludo’.