pytest stuck after assertion fail

pepoluan commented 4 years ago

Detailed Description

I'm writing pytest test cases for aiosmtpd, and I'm hitting this problem against master in aio-libs/aiosmtpd

Minimal reproducible bug as follows:

import asyncio
import pytest

from aiosmtpd.controller import Controller
from aiosmtpd.handlers import Sink
from aiosmtpd.smtp import SMTP as Server
from smtplib import SMTP

SERVER_ADDRESS = ("localhost", 8025)

def authenticator(mechanism, login, password):
    if login and login.decode() == 'goodlogin':
        return True
    else:
        return False

class DecodingController(Controller):
    def factory(self):
        return Server(self.handler, decode_data=True, enable_SMTPUTF8=True,
                      auth_require_tls=False, auth_callback=authenticator)

@pytest.fixture
def temp_loop() -> asyncio.AbstractEventLoop:
    default_loop = asyncio.get_event_loop()
    new_loop = asyncio.new_event_loop()
    asyncio.set_event_loop(new_loop)
    #
    yield new_loop
    #
    new_loop.close()
    asyncio.set_event_loop(default_loop)

@pytest.fixture
def decoding_controller(temp_loop):
    controller = DecodingController(Sink, loop=temp_loop)
    controller.start()
    temp_loop.call_later(3.0, temp_loop.stop)
    #
    print("@@@ yielding @@@")
    yield controller
    print("@@@ returning @@@")
    #
    controller.stop()

@pytest.fixture
def client():
    print(">>> entering <<<")
    with SMTP(*SERVER_ADDRESS) as smtp_client:
        yield smtp_client
    print(">>> exited <<<")

@pytest.mark.usefixtures("decoding_controller")
class TestSMTPNieuw:

    def test_data_abortconn(self, client):
        code, _ = client.helo("example.com")
        assert code == 250
        code, _ = client.docmd("MAIL FROM: <alice@example.org>")
        assert code == 250
        code, _ = client.docmd("RCPT TO: <bob@example.org>")
        assert code == 250
        print("###SENDING_DATA###")
        code, _ = client.docmd("DATA")
        assert code == 250  # I purposefully fail here
        print("###ASSERT_SUCCESS###")

Running the above inside PyCharm's Terminal window produces this:

Microsoft Windows [Version 10.0.19041.508]
(c) 2020 Microsoft Corporation. All rights reserved.

(aiosmtpd-10-cp36) C:\Repos\aiosmtpd>pytest -vvvv -s aiosmtpd\tests\test_smtp_problem.py
=========================================== test session starts ===========================================
platform win32 -- Python 3.6.8, pytest-6.1.1, py-1.9.0, pluggy-0.13.1 -- c:\repos\venvs\aiosmtpd-10-cp36\scripts\python.exe
cachedir: .pytest_cache
rootdir: C:\Repos\aiosmtpd
plugins: mock-3.3.1
collected 1 item

aiosmtpd/tests/test_smtp_problem.py::TestSMTPNieuw::test_data_abortconn @@@ yielding @@@
>>> entering <<<
###SENDING_DATA###
FAILED

... then pytest just got stuck there, not responding to anything, I can't even do Ctrl-C and I have to terminate the Terminal process.

`pip list`

Package            Version
------------------ -------
atomicwrites       1.4.0
atpublic           2.1.1
attrs              20.2.0
colorama           0.4.4
importlib-metadata 2.0.0
iniconfig          1.1.1
packaging          20.4
pip                20.2.4
pluggy             0.13.1
py                 1.9.0
pyparsing          2.4.7
pytest             6.1.2
pytest-mock        3.3.1
setuptools         50.3.2
six                1.15.0
toml               0.10.2
typing-extensions  3.7.4.3
zipp               3.4.0

(I actually only installed 3 packages: atpublic, pytest, and pytest-mock; the other packages are the dependencies of those three.)

pytest & OS versions

(aiosmtpd-11-cp36) C:\Repos\aiosmtpd>pytest -V
pytest 6.1.2

(aiosmtpd-11-cp36) C:\Repos\aiosmtpd>ver
Microsoft Windows [Version 10.0.19041.508]

(aiosmtpd-11-cp36) C:\Repos\aiosmtpd>python -V
Python 3.6.8

Minimal example

See "Detailed Description" above

[x] a detailed description of the bug or problem you are having
[x] output of pip list from the virtual environment you are using
[x] pytest and operating system versions
[x] minimal example if possible

Zac-HD commented 4 years ago

Try with:

@pytest.fixture
def temp_loop() -> asyncio.AbstractEventLoop:
    default_loop = asyncio.get_event_loop()
    new_loop = asyncio.new_event_loop()
    asyncio.set_event_loop(new_loop)
    try:
        yield new_loop
    finally:
        new_loop.close()
        asyncio.set_event_loop(default_loop)

@pytest.fixture
def decoding_controller(temp_loop):
    controller = DecodingController(Sink, loop=temp_loop)
    controller.start()
    temp_loop.call_later(3.0, temp_loop.stop)
    #
    print("@@@ yielding @@@")
    try:
        yield controller
    else:
        #
        print("@@@ returning @@@")
    finally:
        controller.stop()

Failing to clean up on failure can cause all kinds of weird and hard-to-identify issues. If that doesn't fix it someone else will have to help though :sweat_smile:

pepoluan commented 4 years ago

@Zac-HD so I implemented your suggestion (except for the else: clause in decoding_controller -- need an except: if I want to use else there)

The fixtures are now as such:

@pytest.fixture
def temp_loop() -> asyncio.AbstractEventLoop:
    default_loop = asyncio.get_event_loop()
    new_loop = asyncio.new_event_loop()
    asyncio.set_event_loop(new_loop)
    try:
        #
        print("!!! new loop !!!")
        yield new_loop
        #
    finally:
        print("!!! return to default_loop !!!")
        new_loop.close()
        asyncio.set_event_loop(default_loop)

@pytest.fixture
def decoding_controller(temp_loop):
    controller = DecodingController(Sink, loop=temp_loop)
    controller.start()
    temp_loop.call_later(3.0, temp_loop.stop)
    try:
        #
        print("@@@ yielding @@@")
        yield controller
        #
    finally:
        print("@@@ returning @@@")
        controller.stop()

@pytest.fixture
def client():
    print(">>> entering <<<")
    with SMTP(*SERVER_ADDRESS) as smtp_client:
        yield smtp_client
    print(">>> exited <<<")

Executing:

(aiosmtpd-11-cp36) C:\Repos\aiosmtpd>pytest -vvvv -s aiosmtpd\tests\test_smtp_problem.py
=========================================== test session starts ===========================================
platform win32 -- Python 3.6.8, pytest-6.1.2, py-1.9.0, pluggy-0.13.1 -- c:\repos\venvs\aiosmtpd-11-cp36\scr
ipts\python.exe
cachedir: .pytest_cache
rootdir: C:\Repos\aiosmtpd
plugins: mock-3.3.1
collected 1 item                                                                                           

aiosmtpd/tests/test_smtp_problem.py::TestSMTPNieuw::test_data_abortconn !!! new loop !!!
@@@ yielding @@@
>>> entering <<<
###SENDING_DATA###
FAILED

No joy. pytest still got stuck after printing "FAILED". Can't Ctrl-C, had to kill.

pepoluan commented 4 years ago

Just to add, replacing the line

        assert code == 250  # I purposefully fail here

with

        if code != 250:
            pytest.fail()

also hangs.

Somehow pytest just got stuck there and never call any finalizers.

pepoluan commented 4 years ago

Just to add: Running in a standalone PowerShell 7 window (in a virtualenv) also hangs; but this time I can Ctrl-Break to terminate the process. (Ctrl-C still not working)

(test15) PS C:\Repos\aiosmtpd> pytest -vvv -s .\aiosmtpd\tests\test_smtp_problem.py
==================================================================== test session starts =====================================================================
platform win32 -- Python 3.8.2, pytest-6.1.2, py-1.9.0, pluggy-0.13.1 -- c:\python\envs\test15\scripts\python.exe
cachedir: .pytest_cache
rootdir: C:\Repos\aiosmtpd
collected 1 item

aiosmtpd/tests/test_smtp_problem.py::TestSMTPNieuw::test_data_abortconn !!! new loop !!!
@@@ yielding @@@
>>> entering <<<
###SENDING_DATA###
FAILED

pepoluan commented 4 years ago

Update: Currently I'll use this workaround in the test case:

@pytest.mark.usefixtures("decoding_controller")
class TestSMTPNieuw:

    def test_data_abortconn(self, decoding_controller, client):
        print("###SENDING_HELO###")
        code, _ = client.helo("example.com")
        assert code == 250
        print("###SENDING_MAIL###")
        code, _ = client.docmd("MAIL FROM: <alice@example.org>")
        assert code == 250
        print("###SENDING_RCPT###")
        code, _ = client.docmd("RCPT TO: <bob@example.org>")
        assert code == 250
        print("###SENDING_DATA###")
        code, _ = client.docmd("DATA")
        decoding_controller.stop()
        assert code == 250  # This purposefully fails
        print("###ASSERT_SUCCESS###")

Result:

============================ test session starts =============================
platform win32 -- Python 3.6.8, pytest-6.1.2, py-1.9.0, pluggy-0.13.1 -- c:\rep
os\venvs\aiosmtpd-11-cp36\scripts\python.exe
cachedir: .pytest_cache
rootdir: C:\Repos\aiosmtpd
plugins: mock-3.3.1
collected 1 item                                                              

aiosmtpd/tests/test_smtp_problem.py::TestSMTPNieuw::test_data_abortconn !!! new
 loop !!!
@@@ yielding @@@
>>> entering <<<
###SENDING_HELO###
###SENDING_MAIL###
###SENDING_RCPT###
###SENDING_DATA###
FAILED>>> exited <<<
@@@ returning @@@
@@@ already stopped @@@
!!! return to default_loop !!!

================================== FAILURES ==================================
_____________________ TestSMTPNieuw.test_data_abortconn ______________________

self = <aiosmtpd.tests.test_smtp_problem.TestSMTPNieuw object at 0x000001AF0E30
BE10>
decoding_controller = <aiosmtpd.tests.test_smtp_problem.DecodingController obje
ct at 0x000001AF0E331160>
client = <smtplib.SMTP object at 0x000001AF0E331320>

    def test_data_abortconn(self, decoding_controller, client):
        print("###SENDING_HELO###")
        code, _ = client.helo("example.com")
        assert code == 250
        print("###SENDING_MAIL###")
        code, _ = client.docmd("MAIL FROM: <alice@example.org>")
        assert code == 250
        print("###SENDING_RCPT###")
        code, _ = client.docmd("RCPT TO: <bob@example.org>")
        assert code == 250
        print("###SENDING_DATA###")
        code, _ = client.docmd("DATA")
        decoding_controller.stop()
>       assert code == 250  # This purposefully fails
E       assert 354 == 250
E         +354
E         -250

aiosmtpd\tests\test_smtp_problem.py:84: AssertionError
========================== short test summary info ===========================
FAILED aiosmtpd/tests/test_smtp_problem.py::TestSMTPNieuw::test_data_abortconn
============================= 1 failed in 0.13s ==============================

(aiosmtpd-11-cp36) C:\Repos\aiosmtpd>

(This requires an adaptation in the fixture because controller does not like .stop() to be called twice.)

So again this seems that for some reasons pytest does not call the finalizer for the decoding_controller fixture during the first version's assertion fail.

pepoluan commented 4 years ago

Update: Wrapping the test steps in try...finally also works:

@pytest.mark.usefixtures("decoding_controller")
class TestSMTPNieuw:

    def test_data_abortconn(self, decoding_controller, client):
        try:
            print("###SENDING_HELO###")
            code, _ = client.helo("example.com")
            assert code == 250
            print("###SENDING_MAIL###")
            code, _ = client.docmd("MAIL FROM: <alice@example.org>")
            assert code == 250
            print("###SENDING_RCPT###")
            code, _ = client.docmd("RCPT TO: <bob@example.org>")
            assert code == 250
            print("###SENDING_DATA###")
            code, _ = client.docmd("DATA")
            assert code == 250  # This purposefully fails
            print("###ASSERT_SUCCESS###")
        finally:
            decoding_controller.stop()

laplasz commented 2 years ago

same issue here!! my problem is that it randomly occurs - also just happening when more than one test module is executed by pytest. executing with python3 -m unittest no issue at all. version is - 6.2.5

pytest-dev / pytest