bug#42740: Segfault in libssh during ‘guix copy’

[Artyom Poptsov <poptsov.artyom@gmail.com>]

Hello Ludovic,

please check if this branch will work without segfaults in Guix:
  https://github.com/artyom-poptsov/guile-ssh/tree/wip-fix-segfaults-on-gc

Key changes:

- Channels are now protecting the parent session from GC'ing.

- Every channel procedure now ensures that the parent session is
  connected before calling any libssh procedures upon a channel
  instance.  The idea is that a channel cannot be created when a session
  is disconnected and when channel is present and the session is closed,
  it means that the session is disconnected and freed.

- Artyom

On Fri, 7 Aug 2020 at 12:25, Ludovic Courtès <ludo@gnu.org> wrote:
>
> Hi,
>
> I observe the following segfault:
>
> --8<---------------cut here---------------start------------->8---
> $ guix copy --to=olimex /gnu/store/… -v3 --debug=3
> sending 66 store items (166 MiB) to 'A20-OLinuXino.local'...
> exporting path `/gnu/store/als3v92k7l6ny44sci1x0p9x6d7z0ivp-mesa-20.0.8'
> Adres-eraro(nekropsio elŝutita)
> $ guix describe
> Generacio 152   Aug 04 2020 17:34:23    (nuna)
>   guix abe3c5e
>     repository URL: https://git.savannah.gnu.org/git/guix.git
>     branch: master
>     commit: abe3c5ed7d04985c987e6c81aeb1284354ea0c77
> $ gdb  $(type -P guile) core
>
> [...]
>
> [Current thread is 1 (Thread 0x7f947b084b80 (LWP 12777))]
> (gdb) bt
> #0  0x00007f94751c0185 in deflate_fast ()
>    from /gnu/store/rykm237xkmq7rl1p0nwass01p090p88x-zlib-1.2.11/lib/libz.so.1
> #1  0x00007f94751c253d in deflate () from /gnu/store/rykm237xkmq7rl1p0nwass01p090p88x-zlib-1.2.11/lib/libz.so.1
> #2  0x00007f9474a8db4a in gzip_compress (session=session@entry=0x1ff0b10, source=source@entry=0x1ff07e0,
>     level=<optimized out>) at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/gzip.c:91
> #3  0x00007f9474a8de83 in compress_buffer (session=session@entry=0x1ff0b10, buf=0x1ff07e0)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/gzip.c:112
> #4  0x00007f9474a6ab5f in packet_send2 (session=session@entry=0x1ff0b10)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/packet.c:1632
> #5  0x00007f9474a6ac32 in ssh_packet_send (session=session@entry=0x1ff0b10)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/packet.c:1810
> #6  0x00007f9474a54639 in channel_write_common (channel=0x1ff43a0, data=0x7f9477995020, len=65536, is_stderr=0)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/channels.c:1488
> #7  0x00007f9474ad8a9e in write_to_channel_port ()
>    from /gnu/store/vj92bd6lcknylwka9v4n4h0i360n6vn4-guile-ssh-0.13.0/lib/libguile-ssh.so.13
> #8  0x00007f947b749edc in scm_i_write_bytes (port=#<port #<port-type channel 7f9476af56c0> 7f9477c23e00>,
>     src="#<vu8vector>" = {...}, start=0, count=65536) at ports.c:2865
> #9  0x00007f947b75186f in scm_put_bytevector (port=#<port #<port-type channel 7f9476af56c0> 7f9477c23e00>,
>     bv="#<vu8vector>" = {...}, start=<optimized out>, count=<optimized out>) at r6rs-ports.c:676
> #10 0x00007f94750be427 in ?? ()
> #11 0x00007f947ad60d80 in ?? ()
> #12 0x00007f947b7ee620 in ?? () from /gnu/store/0w76khfspfy8qmcpjya41chj3bgfcy0k-guile-3.0.4/lib/libguile-3.0.so.1
> #13 0x00007f947ad60d80 in ?? ()
> #14 0x00007f947b72743b in scm_jit_enter_mcode (thread=0x7f947ad60d80, thread@entry=0x28,
>     mcode=0x7f94750c63a0 "I\211\314I)\304I\203\374\020\017\214k ") at jit.c:5852
> #15 0x00007f947b7828e9 in vm_regular_engine (thread=0x28) at vm-engine.c:360
> #16 0x00007f947b7835b5 in scm_call_n (proc=<optimized out>, argv=argv@entry=0x7fff14699b38, nargs=nargs@entry=1)
>     at vm.c:1608
> #17 0x00007f947b700c97 in scm_primitive_eval (exp=<optimized out>) at eval.c:671
> #18 0x00007f947b7290fb in scm_primitive_load (filename=<optimized out>) at load.c:131
> #19 0x00007f947b782151 in vm_regular_engine (thread=0x7f947ad60d80) at vm-engine.c:972
> #20 0x00007f947b7835b5 in scm_call_n (proc=<optimized out>, argv=argv@entry=0x7fff14699d08, nargs=nargs@entry=1)
>     at vm.c:1608
> #21 0x00007f947b700c97 in scm_primitive_eval (exp=<optimized out>,
>     exp@entry=((@ (ice-9 control) %) (begin ((@@ (ice-9 command-line) load/lang) "/home/ludo/.config/guix/current/bin/guix") (quit)))) at eval.c:671
> #22 0x00007f947b700cf3 in scm_eval (
>     exp=((@ (ice-9 control) %) (begin ((@@ (ice-9 command-line) load/lang) "/home/ludo/.config/guix/current/bin/guix") (quit))), module_or_state=module_or_state@entry="#<struct module>" = {...}) at eval.c:705
> #23 0x00007f947b7595a0 in scm_shell (argc=8, argv=0x7fff1469a378) at script.c:357
> #24 0x00007f947b7186ad in invoke_main_func (body_data=0x7fff1469a210) at init.c:308
> #25 0x00007f947b6fab2a in c_body (d=0x7fff1469a150) at continuations.c:430
> #26 0x00007f947b782151 in vm_regular_engine (thread=0x7f947ad60d80) at vm-engine.c:972
> #27 0x00007f947b7835b5 in scm_call_n (proc=<optimized out>, argv=argv@entry=0x7fff14699f10, nargs=nargs@entry=2)
>     at vm.c:1608
> #28 0x00007f947b6ffb2a in scm_call_2 (proc=<optimized out>, arg1=<optimized out>, arg2=<optimized out>)
>     at eval.c:503
> #29 0x00007f947b70132a in scm_c_with_exception_handler (type=type@entry=#t,
>     handler=handler@entry=0x7f947b7787e0 <catch_post_unwind_handler>,
>     handler_data=handler_data@entry=0x7fff1469a080, thunk=thunk@entry=0x7f947b778920 <catch_body>,
>     thunk_data=thunk_data@entry=0x7fff1469a080) at exceptions.c:170
> #30 0x00007f947b778b1d in scm_c_catch (tag=tag@entry=#t, body=body@entry=0x7f947b6fab20 <c_body>,
>     body_data=body_data@entry=0x7fff1469a150, handler=handler@entry=0x7f947b6fadc0 <c_handler>,
>     handler_data=handler_data@entry=0x7fff1469a150,
>     pre_unwind_handler=pre_unwind_handler@entry=0x7f947b6fac20 <pre_unwind_handler>,
>     pre_unwind_handler_data=0x7f9479037240) at throw.c:168
> #31 0x00007f947b6fb0d3 in scm_i_with_continuation_barrier (body=body@entry=0x7f947b6fab20 <c_body>,
>     body_data=body_data@entry=0x7fff1469a150, handler=handler@entry=0x7f947b6fadc0 <c_handler>,
>     handler_data=handler_data@entry=0x7fff1469a150,
>     pre_unwind_handler=pre_unwind_handler@entry=0x7f947b6fac20 <pre_unwind_handler>,
>     pre_unwind_handler_data=0x7f9479037240) at continuations.c:368
> #32 0x00007f947b6fb165 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>)
>     at continuations.c:464
> #33 0x00007f947b7775bf in with_guile (base=0x7fff1469a1b8, data=0x7fff1469a1e0) at threads.c:645
> #34 0x00007f947b65ca68 in GC_call_with_stack_base ()
>    from /gnu/store/iycnpxxrg8m9wf9w58d6zvp9sdby6m9d-libgc-7.6.12/lib/libgc.so.1
> #35 0x00007f947b7778d8 in scm_i_with_guile (dynamic_state=<optimized out>, data=data@entry=0x7fff1469a1e0,
>     func=func@entry=0x7f947b718690 <invoke_main_func>) at threads.c:688
> #36 scm_with_guile (func=func@entry=0x7f947b718690 <invoke_main_func>, data=data@entry=0x7fff1469a210)
>     at threads.c:694
> #37 0x00007f947b718822 in scm_boot_guile (argc=argc@entry=8, argv=argv@entry=0x7fff1469a378,
>     main_func=main_func@entry=0x401240 <inner_main>, closure=closure@entry=0x0) at init.c:291
> #38 0x0000000000401100 in main (argc=8, argv=0x7fff1469a378) at guile.c:95
> (gdb) frame 3
> #3  0x00007f9474a8de83 in compress_buffer (session=session@entry=0x1ff0b10, buf=0x1ff07e0)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/gzip.c:112
> 112     /tmp/guix-build-libssh-0.9.4.drv-0/source/src/gzip.c: Dosiero aŭ dosierujo ne ekzistas.
> (gdb) p *session
> $1 = {common = {error = {error_code = 0, error_buffer = '\000' <repeats 1023 times>}, callbacks = 0x0,
>     log_verbosity = 0}, socket = 0x1ff0720, serverbanner = 0x1ff1e00 "SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u1",
>   clientbanner = 0x1ff15d0 "SSH-2.0-libssh_0.9.3", protoversion = 0, server = 0, client = 1, openssh = 395008,
>   send_seq = 437, recv_seq = 157, last_rekey_time = {seconds = 0, useconds = 0}, connected = 1, alive = 1,
>   flags = 3, extensions = 0, banner = 0x0, discon_msg = 0x0, in_buffer = 0x1ff0810, in_packet = {valid = 1,
>     len = 0, type = 93 ']'}, out_buffer = 0x1ff07e0, out_queue = 0x1ff03f0,
>   pending_call_state = SSH_PENDING_CALL_NONE, session_state = SSH_SESSION_STATE_AUTHENTICATED,
>   packet_state = PACKET_STATE_INIT, dh_handshake_state = DH_STATE_FINISHED,
>   global_req_state = SSH_CHANNEL_REQ_STATE_NONE, agent_state = 0x0, auth = {auto_state = 0x1ff72b0,
>     service_state = SSH_AUTH_SERVICE_ACCEPTED, state = SSH_AUTH_STATE_SUCCESS, supported_methods = 6,
>     current_method = 0}, first_kex_follows_guess_wrong = 0, in_hashbuf = 0x0, out_hashbuf = 0x0,
>   current_crypto = 0x1ff0480, next_crypto = 0x1ff7b90, channels = 0x1ff7290, maxchannel = 45, agent = 0x1ff0840,
>   kbdint = 0x0, gssapi = 0x0, srv = {rsa_key = 0x0, dsa_key = 0x0, ecdsa_key = 0x0, ed25519_key = 0x0,
>     hostkey = SSH_KEYTYPE_UNKNOWN, hostkey_digest = SSH_DIGEST_AUTO}, ssh_message_list = 0x0,
>   ssh_message_callback = 0x0, ssh_message_callback_data = 0x0, server_callbacks = 0x0,
>   ssh_connection_callback = 0x7f9474a58b30 <ssh_client_connection_callback>, default_packet_callbacks = {
>     start = 1 '\001', n_callbacks = 100 'd', callbacks = 0x7f9474acb380 <default_packet_handlers>,
>     user = 0x1ff0b10}, packet_callbacks = 0x1ff1610, socket_callbacks = {userdata = 0x1ff0b10,
>     data = 0x7f9474a6b030 <ssh_packet_socket_callback>,
>     controlflow = 0x7f9474a6a0e0 <ssh_packet_socket_controlflow_callback>,
>     exception = 0x7f9474a72830 <ssh_socket_exception_callback>, connected = 0x0}, default_poll_ctx = 0x1ff1dd0,
>   pcap_ctx = 0x0, opts = {identity = 0x1ff1340, username = 0x1ff14a0 "olimex",
>     host = 0x1ff15f0 "A20-OLinuXino.local", bindaddr = 0x0, sshdir = 0x1ff1660 "/home/ludo/.ssh",
>     knownhosts = 0x1ff1680 "/home/ludo/.ssh/known_hosts",
>     global_knownhosts = 0x1ff15a0 "/etc/ssh/ssh_known_hosts", wanted_methods = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0,
>       0x1ff1520 "zlib@openssh.com,zlib", 0x1ff1630 "zlib@openssh.com,zlib", 0x0, 0x0},
>     pubkey_accepted_types = 0x0, ProxyCommand = 0x0, custombanner = 0x0, timeout = 3600, timeout_usec = 0,
>     port = 22, fd = -1, StrictHostKeyChecking = 1, compressionlevel = 3 '\003', gss_server_identity = 0x0,
>     gss_client_identity = 0x0, gss_delegate_creds = 0, flags = 15, nodelay = 1, config_processed = true,
>     options_seen = "\000\000\001\000\001", '\000' <repeats 24 times>, rekey_data = 0, rekey_time = 0},
>   socket_counter = 0x0, raw_counter = 0x0}
> (gdb) info threads
>   Id   Target Id                         Frame
> * 1    Thread 0x7f947b084b80 (LWP 12777) 0x00007f9474a8de83 in compress_buffer (session=session@entry=0x1ff0b10,
>     buf=0x1ff07e0) at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/gzip.c:112
>   2    Thread 0x7f947ad5e700 (LWP 12778) warning: Unexpected size of section `.reg-xstate/12778' in core file.
> 0x00007f947b62b94c in futex_wait_cancelable (private=<optimized out>,
>     expected=0, futex_word=0x7f947b6836ec <mark_cv+44>) at ../sysdeps/nptl/futex-internal.h:183
>   3    Thread 0x7f9478a9b700 (LWP 12781) warning: Unexpected size of section `.reg-xstate/12781' in core file.
> 0x00007f94751c0782 in deflate_fast ()
>    from /gnu/store/rykm237xkmq7rl1p0nwass01p090p88x-zlib-1.2.11/lib/libz.so.1
>   4    Thread 0x7f947a3cd700 (LWP 12779) warning: Unexpected size of section `.reg-xstate/12779' in core file.
> 0x00007f947b62b94c in futex_wait_cancelable (private=<optimized out>,
>     expected=0, futex_word=0x7f947b6836ec <mark_cv+44>) at ../sysdeps/nptl/futex-internal.h:183
>   5    Thread 0x7f94767d6700 (LWP 12782) warning: Unexpected size of section `.reg-xstate/12782' in core file.
> 0x00007f947b62f0a4 in __libc_read (fd=11, buf=buf@entry=0x7f94767d5660,
>     nbytes=nbytes@entry=1) at ../sysdeps/unix/sysv/linux/read.c:26
>   6    Thread 0x7f9479a3c700 (LWP 12780) warning: Unexpected size of section `.reg-xstate/12780' in core file.
> 0x00007f947b62b94c in futex_wait_cancelable (private=<optimized out>,
>     expected=0, futex_word=0x7f947b6836ec <mark_cv+44>) at ../sysdeps/nptl/futex-internal.h:183
> (gdb) thread 3
> [Switching to thread 3 (Thread 0x7f9478a9b700 (LWP 12781))]
> #0  0x00007f94751c0782 in deflate_fast ()
>    from /gnu/store/rykm237xkmq7rl1p0nwass01p090p88x-zlib-1.2.11/lib/libz.so.1
> (gdb) bt
> #0  0x00007f94751c0782 in deflate_fast ()
>    from /gnu/store/rykm237xkmq7rl1p0nwass01p090p88x-zlib-1.2.11/lib/libz.so.1
> #1  0x00007f94751c253d in deflate () from /gnu/store/rykm237xkmq7rl1p0nwass01p090p88x-zlib-1.2.11/lib/libz.so.1
> #2  0x00007f9474a8db4a in gzip_compress (session=session@entry=0x1ff0b10, source=source@entry=0x1ff07e0,
>     level=<optimized out>) at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/gzip.c:91
> #3  0x00007f9474a8de83 in compress_buffer (session=session@entry=0x1ff0b10, buf=0x1ff07e0)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/gzip.c:112
> #4  0x00007f9474a6ab5f in packet_send2 (session=session@entry=0x1ff0b10)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/packet.c:1632
> #5  0x00007f9474a6ac32 in ssh_packet_send (session=session@entry=0x1ff0b10)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/packet.c:1810
> #6  0x00007f9474a56178 in ssh_channel_send_eof (channel=channel@entry=0x1ff1fd0)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/channels.c:1250
> #7  0x00007f9474a5623b in ssh_channel_close (channel=0x1ff1fd0)
>     at /tmp/guix-build-libssh-0.9.4.drv-0/source/src/channels.c:1301
> #8  0x00007f9474ad8a56 in ptob_close ()
>    from /gnu/store/vj92bd6lcknylwka9v4n4h0i360n6vn4-guile-ssh-0.13.0/lib/libguile-ssh.so.13
> #9  0x00007f947b747153 in release_port (port=#<port #<port-type channel 7f9476af56c0> 7f9474e9d060>)
>     at ports.c:165
> #10 0x00007f947b74a19b in close_port (port=#<port #<port-type channel 7f9476af56c0> 7f9474e9d060>,
>     explicit=<optimized out>) at ports.c:893
> #11 0x00007f947b70132a in scm_c_with_exception_handler (type=type@entry=#t,
>     handler=handler@entry=0x7f947b7787e0 <catch_post_unwind_handler>,
>     handler_data=handler_data@entry=0x7f9478a9a970, thunk=thunk@entry=0x7f947b778920 <catch_body>,
>     thunk_data=thunk_data@entry=0x7f9478a9a970) at exceptions.c:170
> #12 0x00007f947b778b1d in scm_c_catch (tag=tag@entry=#t, body=body@entry=0x7f947b74a200 <do_close>,
>     body_data=<optimized out>, handler=<optimized out>, handler_data=handler_data@entry=0x0,
>     pre_unwind_handler=pre_unwind_handler@entry=0x0, pre_unwind_handler_data=0x0) at throw.c:168
> #13 0x00007f947b778b3e in scm_internal_catch (tag=tag@entry=#t, body=body@entry=0x7f947b74a200 <do_close>,
>     body_data=<optimized out>, handler=<optimized out>, handler_data=handler_data@entry=0x0) at throw.c:177
> #14 0x00007f947b745d84 in finalize_port (ptr=<optimized out>, data=<optimized out>) at ports.c:710
> #15 0x00007f947b6556ef in GC_invoke_finalizers ()
>    from /gnu/store/iycnpxxrg8m9wf9w58d6zvp9sdby6m9d-libgc-7.6.12/lib/libgc.so.1
> #16 0x00007f947b709e79 in scm_run_finalizers () at finalizers.c:399
> #17 0x00007f947b709efd in finalization_thread_proc (unused=<optimized out>) at finalizers.c:234
> #18 0x00007f947b6fab2a in c_body (d=0x7f9478a9ae50) at continuations.c:430
> #19 0x00007f947b782151 in vm_regular_engine (thread=0x7f947ad60b40) at vm-engine.c:972
> #20 0x00007f947b7835b5 in scm_call_n (proc=<optimized out>, argv=argv@entry=0x7f9478a9ac10, nargs=nargs@entry=2)
>     at vm.c:1608
> #21 0x00007f947b6ffb2a in scm_call_2 (proc=<optimized out>, arg1=<optimized out>, arg2=<optimized out>)
>     at eval.c:503
> #22 0x00007f947b70132a in scm_c_with_exception_handler (type=type@entry=#t,
>     handler=handler@entry=0x7f947b7787e0 <catch_post_unwind_handler>,
>     handler_data=handler_data@entry=0x7f9478a9ad80, thunk=thunk@entry=0x7f947b778920 <catch_body>,
>     thunk_data=thunk_data@entry=0x7f9478a9ad80) at exceptions.c:170
> #23 0x00007f947b778b1d in scm_c_catch (tag=tag@entry=#t, body=body@entry=0x7f947b6fab20 <c_body>,
>     body_data=body_data@entry=0x7f9478a9ae50, handler=handler@entry=0x7f947b6fadc0 <c_handler>,
>     handler_data=handler_data@entry=0x7f9478a9ae50,
>     pre_unwind_handler=pre_unwind_handler@entry=0x7f947b6fac20 <pre_unwind_handler>,
>     pre_unwind_handler_data=0x7f9479037240) at throw.c:168
> #24 0x00007f947b6fb0d3 in scm_i_with_continuation_barrier (body=body@entry=0x7f947b6fab20 <c_body>,
>     body_data=body_data@entry=0x7f9478a9ae50, handler=handler@entry=0x7f947b6fadc0 <c_handler>,
>     handler_data=handler_data@entry=0x7f9478a9ae50,
>     pre_unwind_handler=pre_unwind_handler@entry=0x7f947b6fac20 <pre_unwind_handler>,
>     pre_unwind_handler_data=0x7f9479037240) at continuations.c:368
> #25 0x00007f947b6fb165 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>)
>     at continuations.c:464
> #26 0x00007f947b7775bf in with_guile (base=0x7f9478a9aeb8, data=0x7f9478a9aee0) at threads.c:645
> #27 0x00007f947b65ca68 in GC_call_with_stack_base ()
>    from /gnu/store/iycnpxxrg8m9wf9w58d6zvp9sdby6m9d-libgc-7.6.12/lib/libgc.so.1
> #28 0x00007f947b7778d8 in scm_i_with_guile (dynamic_state=<optimized out>, data=<optimized out>,
>     func=<optimized out>) at threads.c:688
> #29 scm_with_guile (func=<optimized out>, data=<optimized out>) at threads.c:694
> #30 0x00007f947b624f64 in start_thread (arg=0x7f9478a9b700) at pthread_create.c:477
> #31 0x00007f947b17c9af in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
> --8<---------------cut here---------------end--------------->8---
>
> This looks similar to <https://issues.guix.gnu.org/26976#11>: we have a
> finalization thread closing a channel port that is still being used.
> This may be a regression in Guile-SSH 0.13.0.
>
> Does that ring a bell, Artyom?
>
> Thanks,
> Ludo’.
>
>


-- 
Artyom V. Poptsov <poptsov.artyom@gmail.com>
Home page: http://poptsov-artyom.narod.ru/
CADR Hackerspace co-founder: https://cadrspace.ru/
GPG: D0C2 EAC1 3310 822D 98DE  B57C E9C5 A2D9 0898 A02F