search

pytest-dev / pytest-timeout

MIT License
216 stars 64 forks source link

1.4.2: pytest is failing #94

Closed kloczek closed 3 years ago

kloczek commented 3 years ago

Just normal build, install and test cycle used on building package from non-root account:

test_pytest_timeout.py ....F.................. [ 57%] . . [ 60%] test_pytest_timeout.py ...........x.x.. [100%]

================================================================================= FAILURES ================================================================================= _ test_timeout_marker_inheritance __

testdir = <Testdir local('/tmp/pytest-of-tkloczko/pytest-70/test_timeout_marker_inheritance0')>

def test_timeout_marker_inheritance(testdir):
    testdir.makepyfile(
        """
        import time, pytest

        @pytest.mark.timeout(timeout=0.05)
        class TestFoo:

            @pytest.mark.timeout(timeout=0.5)
            def test_foo_2(self):
                time.sleep(0.1)

            def test_foo_1(self):
                time.sleep(0.01)
    """
    )
    result = testdir.runpytest("--timeout=0.01", "-s")
  assert result.ret == 0

E assert <ExitCode.TESTS_FAILED: 1> == 0 E + where <ExitCode.TESTS_FAILED: 1> = <RunResult ret=ExitCode.TESTS_FAILED len(stdout.lines)=124 len(stderr.lines)=0 duration=3.99s>.ret

/home/tkloczko/rpmbuild/BUILD/pytest-timeout-1.4.2/test_pytest_timeout.py:412: AssertionError --------------------------------------------------------------------------- Captured stdout call --------------------------------------------------------------------------- running: /usr/bin/python3 -mpytest --basetemp=/tmp/pytest-of-tkloczko/pytest-70/test_timeout_marker_inheritance0/runpytest-0 --timeout=0.01 -s in: /tmp/pytest-of-tkloczko/pytest-70/test_timeout_marker_inheritance0 ============================= test session starts ============================== platform linux -- Python 3.8.11, pytest-6.2.4, py-1.10.0, pluggy-0.13.1 benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000) Using --randomly-seed=538540448 rootdir: /tmp/pytest-of-tkloczko/pytest-70/test_timeout_marker_inheritance0 plugins: timeout-1.4.2, forked-1.3.0, shutil-1.7.0, virtualenv-1.7.0, expect-1.1.0, httpbin-1.0.0, flake8-1.0.7, betamax-0.8.1, freezegun-0.4.2, case-1.5.3, isort-1.3.0, aspectlib-1.5.2, asyncio-0.15.1, toolbox-0.5, xprocess-0.17.1, aiohttp-0.3.0, checkdocs-2.7.0, mock-3.6.1, rerunfailures-9.1.1, requests-mock-1.9.3, cov-2.12.1, pyfakefs-4.5.0, flaky-3.7.0, hypothesis-6.14.0, benchmark-3.4.1, xdist-2.3.0, pylama-7.7.1, datadir-1.3.1, regressions-2.2.0, cases-3.6.3, Faker-8.10.0, randomly-3.8.0 timeout: 0.01s timeout method: signal timeout func_only: False collected 2 items

test_timeout_marker_inheritance.py EE

==================================== ERRORS ==================================== _ ERROR at setup of TestFoo.test_foo1

request = <SubRequest '_session_faker' for >

@pytest.fixture(scope='session', autouse=True)
def _session_faker(request):
    """Fixture that stores the session level ``Faker`` instance.

    This fixture is internal and is only meant for use within the project.
    Third parties should instead use the ``faker`` fixture for their tests.
    """
    if 'faker_session_locale' in request.fixturenames:
        locale = request.getfixturevalue('faker_session_locale')
    else:
        locale = [DEFAULT_LOCALE]
  return Faker(locale=locale)

/usr/lib/python3.8/site-packages/faker/contrib/pytest/plugin.py:20:

/usr/lib/python3.8/site-packages/faker/proxy.py:61: in init self._factory_map[locale] = Factory.create(locale, providers, generator, includes, /usr/lib/python3.8/site-packages/faker/factory.py:56: in create prov_cls, lang_found = cls._get_provider_class(prov_name, locale) /usr/lib/python3.8/site-packages/faker/factory.py:68: in _get_provider_class provider_class = cls._find_provider_class(provider, locale) /usr/lib/python3.8/site-packages/faker/factory.py:109: in _find_provider_class provider_module = import_module(path)

name = 'faker.providers.person.en_US', package = None

def import_module(name, package=None):
    """Import a module.

    The 'package' argument is required when performing a relative import. It
    specifies the package to use as the anchor point from which to resolve the
    relative import to an absolute import.

    """
    level = 0
    if name.startswith('.'):
        if not package:
            msg = ("the 'package' argument is required to perform a relative "
                   "import for {!r}")
            raise TypeError(msg.format(name))
        for character in name:
            if character != '.':
                break
            level += 1
  return _bootstrap._gcd_import(name[level:], package, level)

E Failed: Timeout >0.05s

/usr/lib64/python3.8/importlib/init.py:127: Failed _ ERROR at setup of TestFoo.test_foo2

request = <SubRequest '_session_faker' for >

@pytest.fixture(scope='session', autouse=True)
def _session_faker(request):
    """Fixture that stores the session level ``Faker`` instance.

    This fixture is internal and is only meant for use within the project.
    Third parties should instead use the ``faker`` fixture for their tests.
    """
    if 'faker_session_locale' in request.fixturenames:
        locale = request.getfixturevalue('faker_session_locale')
    else:
        locale = [DEFAULT_LOCALE]
  return Faker(locale=locale)

/usr/lib/python3.8/site-packages/faker/contrib/pytest/plugin.py:20:

/usr/lib/python3.8/site-packages/faker/proxy.py:61: in init self._factory_map[locale] = Factory.create(locale, providers, generator, includes, /usr/lib/python3.8/site-packages/faker/factory.py:56: in create prov_cls, lang_found = cls._get_provider_class(prov_name, locale) /usr/lib/python3.8/site-packages/faker/factory.py:68: in _get_provider_class provider_class = cls._find_provider_class(provider, locale) /usr/lib/python3.8/site-packages/faker/factory.py:109: in _find_provider_class provider_module = import_module(path)

name = 'faker.providers.person.en_US', package = None

def import_module(name, package=None):
    """Import a module.

    The 'package' argument is required when performing a relative import. It
    specifies the package to use as the anchor point from which to resolve the
    relative import to an absolute import.

    """
    level = 0
    if name.startswith('.'):
        if not package:
            msg = ("the 'package' argument is required to perform a relative "
                   "import for {!r}")
            raise TypeError(msg.format(name))
        for character in name:
            if character != '.':
                break
            level += 1
  return _bootstrap._gcd_import(name[level:], package, level)

E Failed: Timeout >0.05s

/usr/lib64/python3.8/importlib/init.py:127: Failed =========================== short test summary info ============================ ERROR test_timeout_marker_inheritance.py::TestFoo::test_foo_1 - Failed: Timeo... ERROR test_timeout_marker_inheritance.py::TestFoo::test_foo_2 - Failed: Timeo... ============================== 2 errors in 0.27s =============================== ========================================================================= short test summary info ========================================================================== XFAIL test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[ipdb-set_trace()] waiting on https://github.com/pytest-dev/pytest/pull/7207 to allow proper testing XFAIL test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[pydevd-settrace(port=4678)] in need of way to setup pydevd server FAILED test_pytest_timeout.py::test_timeout_marker_inheritance - assert <ExitCode.TESTS_FAILED: 1> == 0 =========================================================== 1 failed, 37 passed, 2 xfailed in 145.30s (0:02:25) ============================================================

kloczek commented 3 years ago

After deselecting failing unit and repeat procedure I found that pytest again failed but in other unit.

+ PYTHONPATH=/home/tkloczko/rpmbuild/BUILDROOT/python-pytest-timeout-1.4.2-5.fc35.x86_64/usr/lib64/python3.8/site-packages:/home/tkloczko/rpmbuild/BUILDROOT/python-pytest-timeout-1.4.2-5.fc35.x86_64/usr/lib/python3.8/site-packages
+ /usr/bin/pytest -ra -k '      not test_timeout_marker_inheritance'
=========================================================================== test session starts ============================================================================
platform linux -- Python 3.8.11, pytest-6.2.4, py-1.10.0, pluggy-0.13.1
benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
Using --randomly-seed=2047680639
rootdir: /home/tkloczko/rpmbuild/BUILD/pytest-timeout-1.4.2, configfile: tox.ini
plugins: timeout-1.4.2, forked-1.3.0, shutil-1.7.0, virtualenv-1.7.0, expect-1.1.0, httpbin-1.0.0, flake8-1.0.7, betamax-0.8.1, freezegun-0.4.2, case-1.5.3, isort-1.3.0, aspectlib-1.5.2, asyncio-0.15.1, toolbox-0.5, xprocess-0.17.1, aiohttp-0.3.0, checkdocs-2.7.0, mock-3.6.1, rerunfailures-9.1.1, requests-mock-1.9.3, cov-2.12.1, pyfakefs-4.5.0, flaky-3.7.0, hypothesis-6.14.0, benchmark-3.4.1, xdist-2.3.0, pylama-7.7.1, datadir-1.3.1, regressions-2.2.0, cases-3.6.3, Faker-8.10.0, randomly-3.8.0
collected 41 items / 1 deselected / 40 selected

test_pytest_timeout.py ................x..Fx..........                                                                                                               [ 79%]
. .                                                                                                                                                                  [ 82%]
test_pytest_timeout.py .......                                                                                                                                       [100%]

================================================================================= FAILURES =================================================================================
_____________________________________________________________________________ test_timeout_env _____________________________________________________________________________

testdir = <Testdir local('/tmp/pytest-of-tkloczko/pytest-72/test_timeout_env0')>, monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7f44a8031b20>

    def test_timeout_env(testdir, monkeypatch):
        testdir.makepyfile(
            """
            import time

            def test_foo():
                time.sleep(2)
        """
        )
        monkeypatch.setitem(os.environ, "PYTEST_TIMEOUT", "0.01")
        result = testdir.runpytest()
>       assert result.ret > 0
E       assert <ExitCode.OK: 0> > 0
E        +  where <ExitCode.OK: 0> = <RunResult ret=ExitCode.OK len(stdout.lines)=31 len(stderr.lines)=0 duration=5.90s>.ret

/home/tkloczko/rpmbuild/BUILD/pytest-timeout-1.4.2/test_pytest_timeout.py:113: AssertionError
--------------------------------------------------------------------------- Captured stdout call ---------------------------------------------------------------------------
running: /usr/bin/python3 -mpytest --basetemp=/tmp/pytest-of-tkloczko/pytest-72/test_timeout_env0/runpytest-0
     in: /tmp/pytest-of-tkloczko/pytest-72/test_timeout_env0
============================= test session starts ==============================
platform linux -- Python 3.8.11, pytest-6.2.4, py-1.10.0, pluggy-0.13.1
benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
Using --randomly-seed=1238023986
rootdir: /tmp/pytest-of-tkloczko/pytest-72/test_timeout_env0
plugins: timeout-1.4.2, forked-1.3.0, shutil-1.7.0, virtualenv-1.7.0, expect-1.1.0, httpbin-1.0.0, flake8-1.0.7, betamax-0.8.1, freezegun-0.4.2, case-1.5.3, isort-1.3.0, aspectlib-1.5.2, asyncio-0.15.1, toolbox-0.5, xprocess-0.17.1, aiohttp-0.3.0, checkdocs-2.7.0, mock-3.6.1, rerunfailures-9.1.1, requests-mock-1.9.3, cov-2.12.1, pyfakefs-4.5.0, flaky-3.7.0, hypothesis-6.14.0, benchmark-3.4.1, xdist-2.3.0, pylama-7.7.1, datadir-1.3.1, regressions-2.2.0, cases-3.6.3, Faker-8.10.0, randomly-3.8.0
timeout: 0.01s
timeout method: signal
timeout func_only: False
collected 1 item

test_timeout_env.py .                                                    [100%]

=============================== warnings summary ===============================
test_timeout_env.py::test_foo
  /usr/lib/python3.8/site-packages/_pytest/unraisableexception.py:78: PytestUnraisableExceptionWarning: Exception ignored in: <function _get_module_lock.<locals>.cb at 0x7f8825723ee0>

  Traceback (most recent call last):
    File "<frozen importlib._bootstrap>", line 182, in cb
    File "/home/tkloczko/rpmbuild/BUILDROOT/python-pytest-timeout-1.4.2-5.fc35.x86_64/usr/lib/python3.8/site-packages/pytest_timeout.py", line 200, in handler
      timeout_sigalrm(item, params.timeout)
    File "/home/tkloczko/rpmbuild/BUILDROOT/python-pytest-timeout-1.4.2-5.fc35.x86_64/usr/lib/python3.8/site-packages/pytest_timeout.py", line 375, in timeout_sigalrm
      pytest.fail("Timeout >%ss" % timeout)
    File "/usr/lib/python3.8/site-packages/_pytest/outcomes.py", line 153, in fail
      raise Failed(msg=msg, pytrace=pytrace)
  Failed: Timeout >0.01s

    warnings.warn(pytest.PytestUnraisableExceptionWarning(msg))

-- Docs: https://docs.pytest.org/en/stable/warnings.html
========================= 1 passed, 1 warning in 2.16s =========================
========================================================================= short test summary info ==========================================================================
XFAIL test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[pydevd-settrace(port=4678)]
  in need of way to setup pydevd server
XFAIL test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[ipdb-set_trace()]
  waiting on https://github.com/pytest-dev/pytest/pull/7207 to allow proper testing
FAILED test_pytest_timeout.py::test_timeout_env - assert <ExitCode.OK: 0> > 0
==================================================== 1 failed, 36 passed, 1 deselected, 2 xfailed in 149.03s (0:02:29) =====================================================

I think I know why it failed. I have installed randomly pytest extension which is causing that each time pytest units are executed in random order. Going to uninstall that module and repead test.

kloczek commented 3 years ago

Without randomly still ione unit is failing so looks like there are at least two separated issues. First one that between units are some dependencies and runieng them randomly is causing some fails and second is failing test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[pdb-set_trace()]

+ PYTHONPATH=/home/tkloczko/rpmbuild/BUILDROOT/python-pytest-timeout-1.4.2-5.fc35.x86_64/usr/lib64/python3.8/site-packages:/home/tkloczko/rpmbuild/BUILDROOT/python-pytest-timeout-1.4.2-5.fc35.x86_64/usr/lib/python3.8/site-packages
+ /usr/bin/pytest -ra
=========================================================================== test session starts ============================================================================
platform linux -- Python 3.8.11, pytest-6.2.4, py-1.10.0, pluggy-0.13.1
benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: /home/tkloczko/rpmbuild/BUILD/pytest-timeout-1.4.2, configfile: tox.ini
plugins: timeout-1.4.2, forked-1.3.0, shutil-1.7.0, virtualenv-1.7.0, expect-1.1.0, httpbin-1.0.0, flake8-1.0.7, betamax-0.8.1, freezegun-0.4.2, case-1.5.3, isort-1.3.0, aspectlib-1.5.2, asyncio-0.15.1, toolbox-0.5, xprocess-0.17.1, aiohttp-0.3.0, checkdocs-2.7.0, mock-3.6.1, rerunfailures-9.1.1, requests-mock-1.9.3, cov-2.12.1, ### pyfakefs-4.5.0, flaky-3.7.0, hypothesis-6.14.0, benchmark-3.4.1, xdist-2.3.0, pylama-7.7.1, datadir-1.3.1, regressions-2.2.0, cases-3.6.3, Faker-8.10.0
collected 41 items

. .                                                                                                                                                                  [  2%]
test_pytest_timeout.py ...................................Fxx.                                                                                                       [100%]

================================================================================= FAILURES =================================================================================
____________________________________________________ test_suppresses_timeout_when_debugger_is_entered[pdb-set_trace()] _____________________________________________________

testdir = <Testdir local('/tmp/pytest-of-tkloczko/pytest-74/test_suppresses_timeout_when_debugger_is_entered0')>, debugging_module = 'pdb'
debugging_set_trace = 'set_trace()'

    @pytest.mark.parametrize(
        ["debugging_module", "debugging_set_trace"],
        [
            ("pdb", "set_trace()"),
            pytest.param(
                "ipdb",
                "set_trace()",
                marks=pytest.mark.xfail(
                    reason="waiting on https://github.com/pytest-dev/pytest/pull/7207"
                    " to allow proper testing"
                ),
            ),
            pytest.param(
                "pydevd",
                "settrace(port=4678)",
                marks=pytest.mark.xfail(reason="in need of way to setup pydevd server"),
            ),
        ],
    )
    @have_spawn
    def test_suppresses_timeout_when_debugger_is_entered(
        testdir, debugging_module, debugging_set_trace
    ):
        p1 = testdir.makepyfile(
            """
            import pytest, {debugging_module}

            @pytest.mark.timeout(0.1)
            def test_foo():
                {debugging_module}.{debugging_set_trace}
        """.format(
                debugging_module=debugging_module, debugging_set_trace=debugging_set_trace
            )
        )
        child = testdir.spawn_pytest(str(p1))
        child.expect("test_foo")
        time.sleep(0.2)
        child.send("c\n")
        child.sendeof()
        result = child.read().decode().lower()
        if child.isalive():
            child.terminate(force=True)
        assert "timeout >0.01s" not in result
>       assert "fail" not in result
E       AssertionError: assert 'fail' not in ' __________...\x1b[0mc\r\n'
E         'fail' is contained here:
E
E           e       failed: timeout >0.1s
E         ?         ++++
E
E           /usr/lib64/python3.8/importlib/__init__.py:127: failed
...         =========================== short test summary info ============================
E
E         ...Full output truncated (4 lines hidden), use '-vv' to show

/home/tkloczko/rpmbuild/BUILD/pytest-timeout-1.4.2/test_pytest_timeout.py:464: AssertionError
========================================================================= short test summary info ==========================================================================
XFAIL test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[ipdb-set_trace()]
  waiting on https://github.com/pytest-dev/pytest/pull/7207 to allow proper testing
XFAIL test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[pydevd-settrace(port=4678)]
  in need of way to setup pydevd server
FAILED test_pytest_timeout.py::test_suppresses_timeout_when_debugger_is_entered[pdb-set_trace()] - AssertionError: assert 'fail' not in ' __________...\x1b[0mc\r\n'
=========================================================== 1 failed, 37 passed, 2 xfailed in 135.37s (0:02:15) ============================================================
graingert commented 3 years ago

It seems pytest timeout's tests are very timing sensitive and other plugins you have installed are causing the setup to take longer than expected. Try running with fewer plugins installed

flub commented 3 years ago

Your tests look.... weird. But also you seem to be running a version of pytest-timeout which attempted to speed up the test suite by making the timeouts really short. This was a very, very bad idea and has been reverted because it was way to flaky. Rather than blaming plugins or anything I'd suggest you try current master instead.

I'm going to close on the assumption this is caused by the short timeouts, because that's probably the case. If you reckon that's not so feel free to re-open.

kloczek commented 3 years ago

Just tested 1.4.2 + patches on master and no errors. IMO it would be good to make new release.

kloczek commented 3 years ago

Looks like 2.0.0 and 2.0.1 git tags are missing in repo ..

flub commented 3 years ago

Please open a new issue next time :)

But thanks for the heads up, not used to having to use --tags to git push...

kloczek commented 3 years ago

My automation bases on git tags :P Thank you.