Add some tests

[tristanlatr]

Hello,

This is an attempt to clarify the bug #851, there is no fix in this PR, only tests.

The thing is the tests that passes with inv test but NOT with pytest ./tests/timeout.py, the question is what's happening ?

I've seen scripts running for days where I expected to hit the timeout before.

Tell me if you have any insight,

Thanks

[tristanlatr]

inv test passes on my local computer, MacOS…

[neozenith]

Thanks for providing this. I'll have a look deeper into the invoke code to see if I can narrow down the specific parts of the invoke code causing the timeout behaviour. No guarantee on time frames when I'll get to it though.

From a quick skim, I think the answer is somewhere under the invoke/runners.py::_finish method:

https://github.com/pyinvoke/invoke/blob/main/invoke/runners.py#L451-L509

Since it manages a thread for the command being run and a thread for the timeout.

I see your test expects only 2 lines to be printed whilst the command ping -c 3 localhost attempts to check 3 times. An exact check with a timeout isn't guaranteed. So there may be a race condition.

Something like ping -c 10 localhost and checking that len(stdout.split('\n')) < 10 might be a better check, if that makes sense. The timing of the timeout versus the speed of the ping is a random variable so we are getting into the space of statistical tests.

Which might explain the variance in your own tests? I am guessing here. But if you can try that, I'll have a deeper look into the timeouts on my end.

[tristanlatr]

Hi @neozenith,

Thanks for suggesting other checks, it seems not to have changed the behaviour of pytest ./tests/timeout.py (still fails locally):

% pytest ./tests/timeout.py 
====================================================================================== test session starts ======================================================================================
platform darwin -- Python 3.9.10, pytest-4.6.3, py-1.10.0, pluggy-0.13.1
rootdir: /Users/Tristan/Documents/git-repos/invoke, inifile: pytest.ini
plugins: anyio-3.3.0, cov-2.5.1, relaxed-1.1.5
collected 2 items                                                                                                                                                                               

tests/timeout.py FF

=========================================================================================== FAILURES ============================================================================================
________________________________________________________________________________________ test_timeout_1s ________________________________________________________________________________________

    @pytest.mark.skipif(sys.version_info < (3, 7), reason="requires python3.7 or higher (dataclasses)")
    def test_timeout_1s() -> None:
        """
        Test for issue https://github.com/pyinvoke/invoke/issues/851
        """
        r = _run(command="set -euo pipefail\nping -c 10 localhost\necho 'Done'",
                 timeout=1, pty=True, in_stream=False, out_stream=sys.stderr, err_stream=sys.stderr, )
        assert r.failure == "Command timed out after 1 seconds."
        # Ensures no more than 10 lines got printed, for instance:
        # PING localhost (127.0.0.1): 56 data bytes
        # 64 bytes from 127.0.0.1: icmp_seq=0 ttl=64 time=0.053 ms
>       assert len(list(l for l in r.stdout.split('\n') if l.strip('\r\t '))) < 10, r.stdout
E       AssertionError: PING localhost (127.0.0.1): 56 data bytes
E         64 bytes from 127.0.0.1: icmp_seq=0 ttl=64 time=0.076 ms
E         64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.104 ms
E         64 bytes from 127.0.0.1: icmp_seq=2 ttl=64 time=0.070 ms
E         64 bytes from 127.0.0.1: icmp_seq=3 ttl=64 time=0.102 ms
E         64 bytes from 127.0.0.1: icmp_seq=4 ttl=64 time=0.056 ms
E         64 bytes from 127.0.0.1: icmp_seq=5 ttl=64 time=0.102 ms
E         64 bytes from 127.0.0.1: icmp_seq=6 ttl=64 time=0.111 ms
E         64 bytes from 127.0.0.1: icmp_seq=7 ttl=64 time=0.068 ms
E         64 bytes from 127.0.0.1: icmp_seq=8 ttl=64 time=0.100 ms
E         64 bytes from 127.0.0.1: icmp_seq=9 ttl=64 time=0.067 ms
E         
E         --- localhost ping statistics ---
E         10 packets transmitted, 10 packets received, 0.0% packet loss
E         round-trip min/avg/max/stddev = 0.056/0.086/0.111/0.019 ms
E         
E       assert 14 < 10
E        +  where 14 = len(['PING localhost (127.0.0.1): 56 data bytes', '64 bytes from 127.0.0.1: icmp_seq=0 ttl=64 time=0.076 ms', '64 bytes fr...ytes from 127.0.0.1: icmp_seq=3 ttl=64 time=0.102 ms', '64 bytes from 127.0.0.1: icmp_seq=4 ttl=64 time=0.056 ms', ...])
E        +    where ['PING localhost (127.0.0.1): 56 data bytes', '64 bytes from 127.0.0.1: icmp_seq=0 ttl=64 time=0.076 ms', '64 bytes fr...ytes from 127.0.0.1: icmp_seq=3 ttl=64 time=0.102 ms', '64 bytes from 127.0.0.1: icmp_seq=4 ttl=64 time=0.056 ms', ...] = list(<generator object test_timeout_1s.<locals>.<genexpr> at 0x10e285120>)

tests/timeout.py:59: AssertionError

I'll have a deeper look into the timeouts on my end.

Thanks I think the issue resides in the invoke code.

But what weird is that inv test passes locally, but not in the CI... Would it be possible that it's linked to availability of a real tty? But that wouldn't explain why pytest ./tests/timeout.py fails

[tristanlatr]

The CI tests are failing with another error actually:

https://app.circleci.com/pipelines/github/pyinvoke/invoke/129/workflows/3c6671ea-61c1-4780-ad09-c84f6b5c8d1a/jobs/331

[tristanlatr]

I've fixed this issue by hack myself a timeout wrapper for callables suitable to wrap context._run.

You can look at the code here: https://github.com/tristanlatr/security-scans-wrapper/blob/main/scans_wrapper/process.py#L103-L132

It's probably not the cleanest way to handle that, but seem like it works. Do you want to me to add these changes to the minimal wrapper included in my test module? This would make the test pass...

[tristanlatr]

What do you think @neozenith ?