pytest/unittest2 race condition between setUp and tearDown, inbetween tests in a TestCase (likely gc related)

[drfloob]

I've created a min-repro for this issue below. In short, it seems as if either setUp and tearDown are interleaved inbetween tests, or that the effects of setUp and tearDown are interleaved (i.e. garbage collection). I'm able to reproduce this by writing tests that operate on a shared state, and expect a certain order of state transitions. One of these state transitions expects __del__ to be called, or the object garbage collected, before the next test starts. With unittest2, every other test fails due to state transitions happening out of order. If you use unittest instead of unittest2, this problem goes away!

This may be more of a feature than a bug if this is due to inappropriate reliance on __del__, and/or questionable reliance on shared state, but since each test should ideally run in isolation, this seems worth reporting. A test framework might want to make some guarantees/enforcement around gc ordering.

Versions:

$ pytest --version
This is pytest version 3.8.0, imported from /somewhere/python/2.7/lib/python2.7/site-packages/pytest.pyc
setuptools registered plugins:
  pytest-sugar-0.9.1 at /somewhere/python/2.7/lib/python2.7/site-packages/pytest_sugar.py

Min-Repro

# unittest passes all tests, even when duplicated to 100 tests
# from unittest import TestCase

# unittest2 fails literally every other test, even when duplicated to 100 tests
from unittest2 import TestCase

gl = {"state": "torndown"}

class StateHolder(object):
    """A per-test state management object, created in each tests's setUp
    method, and deleted when it goes out of scope via gc. If there is no
    misordering of setup and teardown between tests, if this is run
    single-threaded, and if gc were run reliably after every teardown, this
    should pass all tests."""

    def __init__(self):
        """sets global state to "setup" iff state was previously "torndown".
        raises Exception otherwise."""

        print('initing ... from gl', gl["state"])
        if gl["state"] != "torndown":
            raise Exception("not torn down", gl["state"])
        gl["state"] = "setup"
        print( "initing ... to gl", gl["state"])

    def __del__(self):
        """sets global state to "teardown" iff state was previously "worked".
        raises Exception otherwise."""

        print('deleting ... from gl', gl["state"])
        if gl["state"] != "worked":
            raise Exception("not set up", gl["state"])
        gl["state"] = "torndown"
        print('deleting ... to gl', gl["state"])

class TestSuite(TestCase):

    def setUp(self):
        print('in setUp')
        self.holder = StateHolder()

    def tearDown(self):
        print('in tearDown')
    
    def test_0(self): gl["state"]="worked"
    def test_1(self): gl["state"]="worked"
    def test_2(self): gl["state"]="worked"
    def test_3(self): gl["state"]="worked"

The error

➜  gc_race clear; pytest -sv race.py
Test session starts (platform: darwin, Python 2.7.13, pytest 3.8.0, pytest-sugar 0.9.1)
cachedir: .pytest_cache
rootdir: /Users/me/proj/gc_race, inifile:
plugins: sugar-0.9.1
in setUp
('initing ... from gl', 'torndown')
('initing ... to gl', 'setup')
in tearDown

 race.py::TestSuite.test_0 ✓                                                                                                                                                            25% ██▌       in setUp
('initing ... from gl', 'worked')
('deleting ... from gl', 'worked')
('deleting ... to gl', 'torndown')


―――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― TestSuite.test_1 ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――

self = <race.TestSuite testMethod=test_1>

    def setUp(self):
        print('in setUp')
>       self.holder = StateHolder()

race.py:40:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <race.StateHolder object at 0x106f800d0>

    def __init__(self):
        """sets global state to "setup" iff state was previously "torndown".
            raises Exception otherwise."""

        print('initing ... from gl', gl["state"])
        if gl["state"] != "torndown":
>           raise Exception("not torn down", gl["state"])
E           Exception: ('not torn down', 'worked')

race.py:22: Exception

 race.py::TestSuite.test_1 ⨯                                                                                                                                                            50% █████     in setUp
('initing ... from gl', 'torndown')
('initing ... to gl', 'setup')
in tearDown

 race.py::TestSuite.test_2 ✓                                                                                                                                                            75% ███████▌  in setUp
('initing ... from gl', 'worked')


―――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― TestSuite.test_3 ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――

self = <race.TestSuite testMethod=test_3>

    def setUp(self):
        print('in setUp')
>       self.holder = StateHolder()

race.py:40:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <race.StateHolder object at 0x106f80990>

    def __init__(self):
        """sets global state to "setup" iff state was previously "torndown".
            raises Exception otherwise."""

        print('initing ... from gl', gl["state"])
        if gl["state"] != "torndown":
>           raise Exception("not torn down", gl["state"])
E           Exception: ('not torn down', 'worked')

race.py:22: Exception

 race.py::TestSuite.test_3 ⨯                                                                                                                                                           100% ██████████

Results (0.09s):
       2 passed
       2 failed
         - race.py:46 TestSuite.test_1
         - race.py:48 TestSuite.test_3
('deleting ... from gl', 'worked')
('deleting ... to gl', 'torndown')
('deleting ... from gl', 'torndown')
Exception Exception: Exception('not set up', 'torndown') in <bound method StateHolder.__del__ of <race.StateHolder object at 0x106f80990>> ignored
('deleting ... from gl', 'torndown')
Exception Exception: Exception('not set up', 'torndown') in <bound method StateHolder.__del__ of <race.StateHolder object at 0x106f800d0>> ignored
➜  gc_race pytest -v
Test session starts (platform: darwin, Python 2.7.13, pytest 3.8.0, pytest-sugar 0.9.1)
cachedir: .pytest_cache
rootdir: /Users/me/proj/gc_race, inifile:
plugins: sugar-0.9.1


Results (0.01s):

Unittest passing with python unittest

Test session starts (platform: darwin, Python 2.7.13, pytest 3.8.0, pytest-sugar 0.9.1)
cachedir: .pytest_cache
rootdir: /Users/me/proj/gc_race, inifile:
plugins: sugar-0.9.1
in setUp
('initing ... from gl', 'torndown')
('initing ... to gl', 'setup')
in tearDown

('deleting ... from gl', 'worked')
('deleting ... to gl', 'torndown')
 race.py::TestSuite.test_0 ✓                                                                                                                                                            25% ██▌       in setUp
('initing ... from gl', 'torndown')
('initing ... to gl', 'setup')
in tearDown

('deleting ... from gl', 'worked')
('deleting ... to gl', 'torndown')
 race.py::TestSuite.test_1 ✓                                                                                                                                                            50% █████     in setUp
('initing ... from gl', 'torndown')
('initing ... to gl', 'setup')
in tearDown

('deleting ... from gl', 'worked')
('deleting ... to gl', 'torndown')
 race.py::TestSuite.test_2 ✓                                                                                                                                                            75% ███████▌  in setUp
('initing ... from gl', 'torndown')
('initing ... to gl', 'setup')
in tearDown

('deleting ... from gl', 'worked')
('deleting ... to gl', 'torndown')
 race.py::TestSuite.test_3 ✓                                                                                                                                                           100% ██████████

Results (0.04s):
       4 passed

[rbtcollins]

Ah, so yes this is likely a reference kept alive too long in the core running code of unittest2; there was a fix for that in CPython 3.3ish, but it caused a regression on (IIRC) 2.6 - we could reapply that now!