[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.