Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

--maxfail does not work correctly #868

Open
thedomdom opened this issue Jan 16, 2023 · 5 comments
Open

--maxfail does not work correctly #868

thedomdom opened this issue Jan 16, 2023 · 5 comments

Comments

@thedomdom
Copy link

We noticed an issue with pytest-xdist in combination with --maxfail>0.
It is related to #420, but goes even further.
For some reason, tearDownClass is not executed completely at the end of a failed test.

This is an example TestCase where the issue occurs:

class TestCase(unittest.TestCase):
    def setUp(self) -> None:
        logging.info("setUp started")
        for _ in range(4):
            time.sleep(3)
            logging.info("setup running")
        logging.info("setUp executed")
        raise TimeoutError

    def test_1(self):
        pass

    def test_2(self):
        pass

    @classmethod
    def tearDownClass(cls) -> None:
        logging.info("tearDownClass started")
        time.sleep(10)
        logging.info("tearDownClass executed")
Results without pytest-xdist: pytest --maxfail=1 -s --log-cli-level=INFO test_test.py 
================================= test session starts ==================================
platform darwin -- Python 3.7.14, pytest-7.2.0, pluggy-0.13.1
rootdir: /Users/d065057/ML-MEH-Assembly/dar_end_to_end_tests
plugins: xdist-3.1.0, timeout-2.1.0
collected 2 items                                                                      

test_test.py::TestCase::test_1 
------------------------------------ live log call -------------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
FAILED
test_test.py::TestCase::test_2 
------------------------------------ live log call -------------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
FAILED
---------------------------------- live log teardown -----------------------------------
INFO     root:test_test.py:23 tearDownClass started
INFO     root:test_test.py:25 tearDownClass executed


======================================= FAILURES =======================================
___________________________________ TestCase.test_1 ____________________________________

self = <dar_end_to_end_tests.test_test.TestCase testMethod=test_1>

    def setUp(self) -> None:
        logging.info("setUp started")
        for _ in range(4):
            time.sleep(3)
            logging.info("setup running")
        logging.info("setUp executed")
>       raise TimeoutError
E       TimeoutError

test_test.py:13: TimeoutError
---------------------------------- Captured log call -----------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
___________________________________ TestCase.test_2 ____________________________________

self = <dar_end_to_end_tests.test_test.TestCase testMethod=test_2>

    def setUp(self) -> None:
        logging.info("setUp started")
        for _ in range(4):
            time.sleep(3)
            logging.info("setup running")
        logging.info("setUp executed")
>       raise TimeoutError
E       TimeoutError

test_test.py:13: TimeoutError
---------------------------------- Captured log call -----------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
-------------------------------- Captured log teardown ---------------------------------
INFO     root:test_test.py:23 tearDownClass started
INFO     root:test_test.py:25 tearDownClass executed
=============================== short test summary info ================================
FAILED test_test.py::TestCase::test_1 - TimeoutError
FAILED test_test.py::TestCase::test_2 - TimeoutError
================================== 2 failed in 34.12s ==================================
 ~/ML-MEH-Assembly/dar_end_to_end_testspytest_xdist_poc *1 +3 !2 ?2pytest --maxfail=1 -s --log-cli-level=INFO test_test.py
================================= test session starts ==================================
platform darwin -- Python 3.7.14, pytest-7.2.0, pluggy-0.13.1
rootdir: /Users/d065057/ML-MEH-Assembly/dar_end_to_end_tests
plugins: xdist-3.1.0, timeout-2.1.0
collected 2 items                                                                      

test_test.py::TestCase::test_1 
------------------------------------ live log call -------------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
FAILED-------------------------------- live log sessionfinish --------------------------------
INFO     root:test_test.py:23 tearDownClass started
INFO     root:test_test.py:25 tearDownClass executed


======================================= FAILURES =======================================
___________________________________ TestCase.test_1 ____________________________________

self = <dar_end_to_end_tests.test_test.TestCase testMethod=test_1>

    def setUp(self) -> None:
        logging.info("setUp started")
        for _ in range(4):
            time.sleep(3)
            logging.info("setup running")
        logging.info("setUp executed")
>       raise TimeoutError
E       TimeoutError

test_test.py:13: TimeoutError
---------------------------------- Captured log call -----------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
=============================== short test summary info ================================
FAILED test_test.py::TestCase::test_1 - TimeoutError
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
================================== 1 failed in 22.08s ==================================
Results with pytest-xdist: pytest -n 1 --dist loadscope --maxfail=1 -s --log-cli-level=INFO test_test.py

(Executing with this trick to make logs visible)

================================= test session starts ==================================
platform darwin -- Python 3.7.14, pytest-7.2.0, pluggy-0.13.1
rootdir: /Users/d065057/ML-MEH-Assembly/dar_end_to_end_tests
plugins: xdist-3.1.0, timeout-2.1.0
gw0 C/Users/d065057/ML-MEH-Assembly/dar_end_to_end_tests/conftest.py:5: ResourceWarning: unclosed file <_io.TextIOWrapper name=1 mode='w' encoding='UTF-8'>
  sys.stdout = sys.stderr
ResourceWarning: Enable tracemalloc to get the object allocation traceback
[gw0] Python 3.7.14 (default, Sep  6 2022, 23:37:35)  -- [Clang 13.1.6 (clang-1316.0.21.2.5)]
gw0 ok================================= test session starts ==================================
platform darwin -- Python 3.7.14, pytest-7.2.0, pluggy-0.13.1
rootdir: /Users/d065057/ML-MEH-Assembly/dar_end_to_end_tests
plugins: xdist-3.1.0, timeout-2.1.0
collected 2 items                                                                      
gw0 [2]
scheduling tests via LoadScopeScheduling

test_test.py::TestCase::test_1 
test_test.py::TestCase::test_1 
------------------------------------ live log call -------------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
FAILED
[gw0] FAILED test_test.py::TestCase::test_1 
test_test.py::TestCase::test_2 
------------------------------------ live log call -------------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
-------------------------------- live log sessionfinish --------------------------------
INFO     root:test_test.py:23 tearDownClass started


======================================= FAILURES =======================================
___________________________________ TestCase.test_1 ____________________________________
[gw0] darwin -- Python 3.7.14 /Users/d065057/ML-MEH-Assembly/venv/bin/python

self = <dar_end_to_end_tests.test_test.TestCase testMethod=test_1>

    def setUp(self) -> None:
        logging.info("setUp started")
        for _ in range(4):
            time.sleep(3)
            logging.info("setup running")
        logging.info("setUp executed")
>       raise TimeoutError
E       TimeoutError

test_test.py:13: TimeoutError
---------------------------------- Captured log call -----------------------------------
INFO     root:test_test.py:8 setUp started
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:11 setup running
INFO     root:test_test.py:12 setUp executed
=============================== short test summary info ================================
FAILED test_test.py::TestCase::test_1 - TimeoutError
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!! xdist.dsession.Interrupted: stopping after 1 failures !!!!!!!!!!!!!!!!!
================================== 1 failed in 22.42s ==================================

As you can see in the logs, pytest usually (without pytest-xdist) executes setUp only once and then executes tearDownClass until its completion in the end.

Contrary to this, with pytest-xdist, setUp is executed twice: The first time until it is finished, and the second time it is aborted. Moreover, tearDownClass is started, but aborted.

Is this expected behavior? If yes, is this behavior documented somewhere? Do you have any recommendations on how to fix the issue?

The most important point for us would be to always execute tearDownClass fully in the end.
(It would also be good if setUp would only be executed once).
@RonnyPfannschmidt
Copy link
Member

Xdist uses multiple processes setup has to happen in each process, no way around that

@thedomdom
Copy link
Author

Thank you for your reply! I am not sure if we are on the same page:

  • By default, setUp is indeed executed for each test method, independently of using multiple processes.
  • Because of the --maxfail=1 argument, setUp should only be executed once, since the first test already fails (in the setUp). This is also how pytest behaves without xdist.
  • In the above example, there is only one worker (=process?) which loads the whole module at once due to the -n 1 --dist loadscope arguments.
  • As mentioned above, tearDownClass is started, but aborted after some seconds. Can we somehow prevent the abortion?

@RonnyPfannschmidt
Copy link
Member

i have to croscheck, but i belive this may be a distributed systems effect

as more than one test id was send to the process, it runs both

in addition there are teardown timeouts involved, so pytest-xdist might be shutting down a unresponsive worker that still in the sleep

i recommend testing with much smaller times for the behaviour and then upping the numbes until it crumbles,

im currently out of the details of the proocess termination behaviour and wont be able to dig into it myself in near future

so basically while the second setup runs on the worker the coordinator sends the command to shutdown

@thedomdom
Copy link
Author

i recommend testing with much smaller times for the behaviour and then upping the numbes until it crumbles,

Thank you for the recommendation!
This would only help to find the root cause, right?
(Since in our real rest case, we have much longer time frames, so this won't help us.)

so basically while the second setup runs on the worker the coordinator sends the command to shutdown

That makes sense – but what is the explanation for the fact that the tearDownClass method is started afterwards?
If the worker is indeed killed, how can it start the tearDownClass?

Do you think that we could achieve the intended behaviour with figures?
I would describe the expected behavior as follows:

  1. Execute each test method one after another (each including setup) until a test (or its setup method) fails
  2. Always (independent of test success/failure): Execute tearDownClass

@RonnyPfannschmidt
Copy link
Member

currently it is not possible to stop the execution of a second test after the first failed due to the current behaviour

details on teardown need to be verified with how xdist itself shuts down

@Garrett-R Garrett-R mentioned this issue Feb 15, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@RonnyPfannschmidt @thedomdom