[BUG] Flaky tests/unit/sftp_test.py::test_put

[webknjaz]

SUMMARY

This feels similar to #57 but probably has a different root cause.

I think what's happening is sshd not starting fast enough. The wait_for_svc_ready_state helper is supposed to reraise the last connection error but maybe it doesn't, or the healthcheck it implements is not enough, I'm not sure.

ISSUE TYPE

• Bug Report

PYLISSH and LIBSSH VERSION

devel

OS / ENVIRONMENT

CI: https://github.com/ansible/pylibssh/runs/7570950100?check_suite_focus=true#step:13:221

STEPS TO REPRODUCE

See the log. Just run the testing on a slow machine with sshd not starting fast enough.

EXPECTED RESULTS

The test should be stable.

ACTUAL RESULTS

I've pasted the meaningful part of the log below, for history.

[CLICK HERE] Excerpt from the CI log linked above

$ python -m tox -p auto --parallel-live -vvvv -e test-binary-dists
[...]
[gw1] [100%] ERROR tests/unit/sftp_test.py::test_put /home/runner/work/pylibssh/pylibssh/.tox/test-binary-dists/lib/python3.9/site-packages/coverage/inorout.py:535: CoverageWarning: Module pylibsshext was previously imported, but not measured (module-not-measured)
  self.warn(msg, slug="module-not-measured")


==================================== ERRORS ====================================
__________________________ ERROR at setup of test_put __________________________
[gw1] linux -- Python 3.9.13 /home/runner/work/pylibssh/pylibssh/.tox/test-binary-dists/bin/python

sshd_addr = ('127.0.0.1', 50217)
ssh_clientkey_path = PosixPath('/tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/ssh_client_rsa_key')

    @pytest.fixture
    def ssh_client_session(sshd_addr, ssh_clientkey_path):
        """Authenticate against SSHD with a private SSH key.
    
        :yields: Pre-authenticated SSH session.
        :ytype: pylibsshext.session.Session
    
        # noqa: DAR101
        """
        hostname, port = sshd_addr
        ssh_session = Session()
>       ssh_session.connect(
            host=hostname,
            port=port,
            user=getpass.getuser(),
            private_key=ssh_clientkey_path.read_bytes(),
            host_key_checking=False,
            look_for_keys=False,
        )

hostname   = '127.0.0.1'
port       = 50217
ssh_clientkey_path = PosixPath('/tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/ssh_client_rsa_key')
ssh_session = <pylibsshext.session.Session object at 0x7f55b0de4ae0>
sshd_addr  = ('127.0.0.1', 50217)

tests/conftest.py:117: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

>   raise LibsshSessionException("ssh connect failed: %s" % self._get_session_error_str())
E   pylibsshext.errors.LibsshSessionException: ssh connect failed: Socket error: Connection reset by peer

AutoAddPolicy = <class 'pylibsshext.session.AutoAddPolicy'>
Channel    = <class 'pylibsshext.channel.Channel'>
HOST_KEY_AUTO_ADD_MSG_MAP = {-1: ' A serious error happened.', 1: "The server doesn't accept that public key as an authentication token. Try anoth... authenticated, you still have to use another method.", 4: "In nonblocking mode, you've got to call this again later."}
KNOW_HOST_MSG_MAP = {0: 'Host is unknown: ', 2: 'Host key for server has changed: ', 3: 'Host key type for server has changed: '}
LOG_MAP    = {0: 0, 10: 3, 20: 2, 30: 1, ...}
MissingHostKeyPolicy = <class 'pylibsshext.session.MissingHostKeyPolicy'>
OPTS_DIR_MAP = {'add_identity': 7, 'ssh_dir': 5}
OPTS_MAP   = {'gssapi_client_identity': 27, 'gssapi_delegate_credentials': 28, 'gssapi_server_identity': 26, 'host': 0, ...}
RejectPolicy = <class 'pylibsshext.session.RejectPolicy'>
SCP        = <class 'pylibsshext.scp.SCP'>
SFTP       = <class 'pylibsshext.sftp.SFTP'>
Session    = <class 'pylibsshext.session.Session'>
__builtins__ = <builtins>
__doc__    = None
__file__   = '/home/runner/work/pylibssh/pylibssh/.tox/test-binary-dists/lib/python3.9/site-packages/pylibsshext/session.cpython-39-x86_64-linux-gnu.so'
__loader__ = <_frozen_importlib_external.ExtensionFileLoader object at 0x7f55b2188be0>
__name__   = 'pylibsshext.session'
__package__ = 'pylibsshext'
__pyx_capi__ = {'get_libssh_session': <capsule object "ssh_session (struct __pyx_obj_11pylibsshext_7session_Session *)" at 0x7f55b2188720>}
__spec__   = ModuleSpec(name='pylibsshext.session', loader=<_frozen_importlib_external.ExtensionFileLoader object at 0x7f55b2188be0...libssh/pylibssh/.tox/test-binary-dists/lib/python3.9/site-packages/pylibsshext/session.cpython-39-x86_64-linux-gnu.so')
__test__   = {}
inspect    = <module 'inspect' from '/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/inspect.py'>
logging    = <module 'logging' from '/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/logging/__init__.py'>

src/pylibsshext/session.pyx:242: LibsshSessionException
---------------------------- Captured stdout setup -----------------------------
Generating public/private rsa key pair.
Your identification has been saved in /tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/ssh_client_rsa_key
Your public key has been saved in /tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/ssh_client_rsa_key.pub
The key fingerprint is:
SHA256:T/06sSPBDkKsCGSiXfXPG7eRAb1Fuk8AC7xsaI4dNEk ansible-pylibssh integration tests key
The key's randomart image is:
+---[RSA 8192]----+
|     oEo. o. ..  |
|.o  . +... +...  |
|=. . o +... +o   |
|o .   * +o ..=   |
| . . B oS.= * .  |
|  . o + .oo+.*   |
|       . oo..oo  |
|          o +.   |
|           ..o   |
+----[SHA256]-----+
Generating public/private rsa key pair.
Your identification has been saved in /tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/ssh_host_rsa_key
Your public key has been saved in /tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/ssh_host_rsa_key.pub
The key fingerprint is:
SHA256:XAEttzpQjQwBoth1BsjJfh1rwNnsKIZeOZGe4EPM+SU runner@fv-az299-344
The key's randomart image is:
+---[RSA 3072]----+
|ooo+=*=+.=.      |
|.O=E+++ = +.     |
|=o= *= + o..     |
|.o+Bo *. ..      |
|..oo.. .S.       |
| .      o        |
|         .       |
|                 |
|                 |
+----[SHA256]-----+
---------------------------- Captured stderr setup -----------------------------
debug2: load_server_config: filename /dev/null
debug2: load_server_config: done config len = 1
debug2: parse_server_config_depth: config /dev/null len 1
debug1: sshd version OpenSSH_8.2, OpenSSL 1.1.1f  31 Mar 2020
debug1: private host key #0: ssh-rsa SHA256:XAEttzpQjQwBoth1BsjJfh1rwNnsKIZeOZGe4EPM+SU
debug1: setgroups() failed: Operation not permitted
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-D'
debug1: rexec_argv[2]='-f'
debug1: rexec_argv[3]='/dev/null'
debug1: rexec_argv[4]='-o'
debug1: rexec_argv[5]='LogLevel=DEBUG3'
debug1: rexec_argv[6]='-o'
debug1: rexec_argv[7]='HostKey=/tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/ssh_host_rsa_key'
debug1: rexec_argv[8]='-o'
debug1: rexec_argv[9]='PidFile=/tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/sshd.pid'
debug1: rexec_argv[10]='-o'
debug1: rexec_argv[11]='UsePAM=yes'
debug1: rexec_argv[12]='-o'
debug1: rexec_argv[13]='PasswordAuthentication=no'
debug1: rexec_argv[14]='-o'
debug1: rexec_argv[15]='ChallengeResponseAuthentication=no'
debug1: rexec_argv[16]='-o'
debug1: rexec_argv[17]='GSSAPIAuthentication=no'
debug1: rexec_argv[18]='-o'
debug1: rexec_argv[19]='StrictModes=no'
debug1: rexec_argv[20]='-o'
debug1: rexec_argv[21]='PermitEmptyPasswords=yes'
debug1: rexec_argv[22]='-o'
debug1: rexec_argv[23]='PermitRootLogin=yes'
debug1: rexec_argv[24]='-o'
debug1: rexec_argv[25]='Protocol=2'
debug1: rexec_argv[26]='-o'
debug1: rexec_argv[27]='HostbasedAuthentication=no'
debug1: rexec_argv[28]='-o'
debug1: rexec_argv[29]='IgnoreUserKnownHosts=yes'
debug1: rexec_argv[30]='-o'
debug1: rexec_argv[31]='Port=50217'
debug1: rexec_argv[32]='-o'
debug1: rexec_argv[33]='ListenAddress=127.0.0.1'
debug1: rexec_argv[34]='-o'
debug1: rexec_argv[35]='AuthorizedKeysFile=/tmp/pytest-of-runner/pytest-0/popen-gw1/test_put0/sshd/authorized_keys'
debug1: rexec_argv[36]='-o'
debug1: rexec_argv[37]='AcceptEnv=LANG LC_*'
debug1: rexec_argv[38]='-o'
debug1: rexec_argv[39]='Subsystem=sftp internal-sftp'
malloc_consolidate(): invalid chunk size
- generated xml file: /home/runner/work/pylibssh/pylibssh/.test-results/pytest/results.xml -
============================= slowest 10 durations =============================
26.17s setup    tests/unit/sftp_test.py::test_make_sftp
22.41s setup    tests/unit/sftp_test.py::test_put
20.18s setup    tests/unit/scp_test.py::test_get
18.11s setup    tests/unit/channel_test.py::test_read_bulk_response
12.26s setup    tests/unit/sftp_test.py::test_get
10.96s setup    tests/unit/channel_test.py::test_exec_command
9.43s setup    tests/unit/channel_test.py::test_double_close
8.68s setup    tests/unit/channel_test.py::test_channel_exit_status
7.74s setup    tests/integration/sshd_test.py::test_sshd_addr_fixture_port
6.19s setup    tests/unit/scp_test.py::test_put
=========================== short test summary info ============================
XPASS tests/unit/channel_test.py::test_exec_command This test causes SEGFAULT, flakily. Ref: https://github.com/ansible/pylibssh/issues/57
ERROR tests/unit/sftp_test.py::test_put - pylibsshext.errors.LibsshSessionExc...
============== 14 passed, 1 xpassed, 1 error in 89.45s (0:01:29) ===============
*** Aborted
Register dump:

 RAX: 0000000000000000   RBX: 00007fd9ed8f52c0   RCX: 00007fd9edc1c00b
 RDX: 0000000000000000   RSI: 0000559a13489ca0   RDI: 0000000000000002
 RBP: 0000559a13489ff0   R8 : 0000000000000000   R9 : 0000559a13489ca0
 R10: 0000000000000008   R11: 0000000000000246   R12: 0000559a13489f10
 R13: 0000000000000010   R14: 00007fd9ee39a000   R15: 0000000000000001
 RSP: 0000559a13489ca0

 RIP: 00007fd9edc1c00b   EFLAGS: 00000246

 CS: 0033   FS: 0000   GS: 0000

 Trap: 0000000e   Error: 00000004   OldMask: 00000400   CR2: 134ca008

 FPUCW: 0000037f   FPUSW: 00000000   TAG: 00000000
 RIP: 00000000   RDP: 00000000

 ST(0) 0000 0000000000000000   ST(1) 0000 0000000000000000
 ST(2) 0000 0000000000000000   ST(3) 0000 0000000000000000
 ST(4) 0000 0000000000000000   ST(5) 0000 0000000000000000
 ST(6) 0000 0000000000000000   ST(7) 0000 0000000000000000
 mxcsr: 1f80
 XMM0:  000000000000000000000000ffffffff XMM1:  000000000000000000000000ffffffff
 XMM2:  000000000000000000000000ffffffff XMM3:  000000000000000000000000ffffffff
 XMM4:  000000000000000000000000ffffffff XMM5:  000000000000000000000000ffffffff
 XMM6:  000000000000000000000000ffffffff XMM7:  000000000000000000000000ffffffff
 XMM8:  000000000000000000000000ffffffff XMM9:  000000000000000000000000ffffffff
 XMM10: 000000000000000000000000ffffffff XMM11: 000000000000000000000000ffffffff
 XMM12: 000000000000000000000000ffffffff XMM13: 000000000000000000000000ffffffff
 XMM14: 000000000000000000000000ffffffff XMM15: 000000000000000000000000ffffffff

Backtrace:
ERROR: InvocationError for command /usr/bin/catchsegv .tox/test-binary-dists/bin/python -m pytest --cov-config=/home/runner/work/pylibssh/pylibssh/.coveragerc --cov=/home/runner/work/pylibssh/pylibssh/.tox/test-binary-dists/lib/python3.9/site-packages/pylibsshext (exited with code 1)
test-binary-dists finish: run-test  after 113.52 seconds
test-binary-dists start: run-test-post 
test-binary-dists finish: run-test-post  after 0.00 seconds
ERROR: invocation failed (exit code 1)
✖ FAIL test-binary-dists in 1 minute, 55.42 seconds
___________________________________ summary ____________________________________
ERROR:   test-binary-dists: parallel child exit code 1

Error: Process completed with exit code 1.

[kucharskim]

While discussing #645 with @Jakuje I've noticed this GitHub issue. As I need sftp with ansible-libssh I tested does it work on OpenBSD and it doesn't, ends up with SIGSEGV.

I am running 1.2.2 with just diff 17e177d applied.

$ python3 version.py
__full_version__='<pylibsshext v1.2.2 with libssh v0.10.6>'
__libssh_version__='0.10.6'
__version__='1.2.2'
__version_info__=(1, 2, 2)

$ python3 test_sftp1.py
ssh.is_connected=1
<pylibsshext.sftp.SFTP object at 0x5026ab6b280>
['__class__', '__delattr__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__getstate__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__setstate__', '__sizeof__', '__str__', '__subclasshook__', '_get_sftp_error_str', 'close', 'get', 'put']
Closing connection...
Segmentation fault (core dumped) 

$ cat test_sftp1.py
#!/usr/bin/env python3

from pylibsshext.errors import LibsshSessionException
from pylibsshext.session import Session

import logging

HOST = "examplehost1"
USER = "root"
TIMEOUT = 30
PORT = 22

ssh = Session()

#ssh.set_log_level(logging.DEBUG)

try:
    ssh.connect(
        host=HOST,
        user=USER,
        timeout=TIMEOUT,
        port=PORT,
    )
except LibsshSessionException as ex:
    print(f"Failed to connect to {HOST}:{PORT} over SSH: {ex!s}")
    raise

print(f"ssh.is_connected={ssh.is_connected}")

sftp_session = ssh.sftp()
print(sftp_session)
print(dir(sftp_session))

print("Closing connection...", flush=True)
ssh.close()

$ egdb -quiet -batch -x commands.txt -e /usr/local/bin/python3.11 -c python3.11.core
[New process 286100]
Core was generated by `python3.11'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  ssh_channel_send_eof (channel=0xec004c17930) at /usr/obj/ports/libssh-0.10.6/libssh-0.10.6/src/channels.c:1298
1298    /usr/obj/ports/libssh-0.10.6/libssh-0.10.6/src/channels.c: No such file or directory.
+show version
GNU gdb (GDB) 13.2
Copyright (C) 2023 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-unknown-openbsd7.6".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word".
+thread apply all bt

Thread 1 (process 286100):
+bt
#0  ssh_channel_send_eof (channel=0xec004c17930) at /usr/obj/ports/libssh-0.10.6/libssh-0.10.6/src/channels.c:1298
#1  0x00000ec00548ffd5 in sftp_free (sftp=0xec004c10000) at /usr/obj/ports/libssh-0.10.6/libssh-0.10.6/src/sftp.c:367
#2  0x00000ec021dfeeee in __pyx_pf_11pylibsshext_4sftp_4SFTP_2__dealloc__ (__pyx_v_self=0xebfcd30b2b0) at /tmp/.tmp-ansible-pylibssh-pep517-uwt1as9y/src/src/pylibsshext/sftp.c:3602
#3  __pyx_pw_11pylibsshext_4sftp_4SFTP_3__dealloc__ (__pyx_v_self=0xebfcd30b2b0) at /tmp/.tmp-ansible-pylibssh-pep517-uwt1as9y/src/src/pylibsshext/sftp.c:3569
#4  __pyx_tp_dealloc_11pylibsshext_4sftp_SFTP (o=0xebfcd30b2b0) at /tmp/.tmp-ansible-pylibssh-pep517-uwt1as9y/src/src/pylibsshext/sftp.c:5838
#5  0x00000ebfb273ec14 in _Py_Dealloc (op=0xec004c17930) at Objects/object.c:2390
#6  Py_DECREF (op=0xec004c17930) at ./Include/object.h:538
#7  Py_XDECREF (op=0xec004c17930) at ./Include/object.h:602
#8  free_keys_object (keys=0xebfcd3281c0) at Objects/dictobject.c:664
#9  dictkeys_decref (dk=0xebfcd3281c0) at Objects/dictobject.c:324
#10 0x00000ebfb273edf1 in dict_dealloc (mp=0xebfc2948380) at Objects/dictobject.c:2376
#11 0x00000ebfb2756239 in _Py_Dealloc (op=0xec004c17930) at Objects/object.c:2390
#12 Py_DECREF (op=0xec004c17930) at ./Include/object.h:538
#13 Py_XDECREF (op=0xec004c17930) at ./Include/object.h:602
#14 module_dealloc (m=0xebfc293a8e0) at Objects/moduleobject.c:699
#15 0x00000ebfb274035d in _Py_Dealloc (op=0xec004c17930) at Objects/object.c:2390
#16 Py_DECREF (op=0xec004c17930) at ./Include/object.h:538
#17 Py_XDECREF (op=0xec004c17930) at ./Include/object.h:602
#18 insertdict (mp=0xebfc28d5340, key=0xebfc29483b0, hash=-91756086980654096, value=0xebfb2ad6f40 <_Py_NoneStruct>) at Objects/dictobject.c:1304
#19 0x00000ebfb2869db6 in finalize_remove_modules (modules=0xebfc28d5340, verbose=0) at Python/pylifecycle.c:1415
#20 finalize_modules (tstate=0xebfb2a549e0 <_PyRuntime+166184>) at Python/pylifecycle.c:1550
#21 0x00000ebfb2869126 in Py_FinalizeEx () at Python/pylifecycle.c:1833
#22 0x00000ebfb28993f7 in Py_RunMain () at Modules/main.c:686
#23 0x00000ebfb289b095 in pymain_main (args=0x79a85ce44fc8) at Modules/main.c:714
#24 0x00000ebfb289b4bc in Py_BytesMain (argc=<optimized out>, argv=0x79a85ce449a0) at Modules/main.c:738
#25 0x00000ebd7f85994b in ?? ()
#26 0x00000ebd7f859820 in ?? ()
#27 0x0000000000000000 in ?? ()
+info threads
  Id   Target Id         Frame 
* 1    process 286100    ssh_channel_send_eof (channel=0xec004c17930) at /usr/obj/ports/libssh-0.10.6/libssh-0.10.6/src/channels.c:1298
+info locals
rc = <error reading variable rc (Cannot access memory at address 0xffffffffffffffff)>
session = 0xdfdfdfdfdfdfdfdf
err = <optimized out>

[kucharskim]

Huh, maybe this is because I didn't sftp_session.close() in test_sftp1.py 🤔

[kucharskim]

Same code with ssh.scp() doesn't have the crash. I think code should clean up after itself, if user forgets to close()

EDIT: Ah, SCP doesn't have close()