Skip to content

Python 3.12.0 test failure on log entry assert in test_session_command_queue_not_implemented #12

@gertvdijk

Description

@gertvdijk

test_session_command_queue_not_implemented fails on 3.12.0 only, on an assert that an error message must have been logged.

fake_session_should_fail = FakeMtaMilterSession(_socket_connection=FakeSocketConnection(app_factory=<function fake_app_factory.<locals>.app_facto...tions_sent=False, _closed=False, logger=<_LoggerAdapter purepythonmilter.server.session (DEBUG)>, responses_written=[])
caplog = <_pytest.logging.LogCaptureFixture object at 0x7f5368fe2b70>

    async def test_session_command_queue_not_implemented(
        fake_session_should_fail: FakeMtaMilterSession,
        caplog: pytest.LogCaptureFixture,
    ) -> None:
        class NonExistingCommand(commands.BaseCommand):
            pass
    
        done_event = fake_session_should_fail.queue_command(NonExistingCommand())
        await asyncio.wait_for(done_event.wait(), 1)
        assert fake_session_should_fail._commands_consumer_task.done()
        assert isinstance(
            fake_session_should_fail._commands_consumer_task.exception(),
            NotImplementedError,
        )
        errors_logged = [rec for rec in caplog.records if rec.levelno >= logging.ERROR]
>       assert len(errors_logged) == 1
E       assert 0 == 1
E        +  where 0 = len([])

tests/server/test_session.py:160: AssertionError

It is actually logged just fine, but just later on and it seems to be like a race condition. Confirmed by this work-around:

diff --git tests/server/test_session.py tests/server/test_session.py
index e8082fb..d271615 100644
--- tests/server/test_session.py
+++ tests/server/test_session.py
@@ -156,6 +156,7 @@ async def test_session_command_queue_not_implemented(
         fake_session_should_fail._commands_consumer_task.exception(),
         NotImplementedError,
     )
+    await asyncio.sleep(0.1)
     errors_logged = [rec for rec in caplog.records if rec.levelno >= logging.ERROR]
     assert len(errors_logged) == 1
     assert ("Got an exception in the commands consumer task.") in errors_logged[0].msg

But it's really awaiting the done event in the consumer, and it should really have been logged before that event is set. Unsure what's going on and whether the test is just not right or something else is not set up correctly.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions