asyncio subprocess with pytest does not call pipe_data_received

Question

I'd like to use asyncio subprocess with pytest-asyncio and it looks like it doesn't work as expected, my code base on https://docs.python.org/3.11/library/asyncio-protocol.html#loop-subprocess-exec-and-subprocessprotocol Server is working fine on standalone version.

here is my code:

import asyncio
import logging
import sys

logger = logging.getLogger()
logging.basicConfig(level=logging.INFO)


class ServerProtocol(asyncio.SubprocessProtocol):
    def __init__(self, exit_future):
        self.exit_future = exit_future
        self.output = bytearray()
        logger.info("server protocol init")

    def pipe_data_received(self, fd, data):
        logger.info(f"data received: {data}")
        self.output.extend(data)

    def process_exited(self):
        self.exit_future.set_result(True)


class Server:
    def __init__(self):
        self.exit_future = None
        self.transport = None
        self.protocol = None
        logger.info("init server")

    async def run(self):
        self.task = asyncio.create_task(self.run_app())
        await asyncio.sleep(10)  # this 10s sleep is only for standalone run, to check that output is logged

    async def run_app(self):
        logger.info("run app")
        # Get a reference to the event loop as we plan to use
        # low-level APIs.
        loop = asyncio.get_running_loop()

        self.exit_future = asyncio.Future(loop=loop)

        # Create the subprocess controlled by DateProtocol;
        # redirect the standard output into a pipe.
        cmd = "src/example_server.py"
        self.transport, self.protocol = await loop.subprocess_exec(
            lambda: ServerProtocol(self.exit_future),
            sys.executable, cmd,
            stdin=None, stderr=None)
        await asyncio.sleep(0.5)

        # Wait for the subprocess exit using the process_exited()
        # method of the protocol.
        await self.exit_future
        #
        # # Close the stdout pipe.
        # self.transport.close()


if __name__ == '__main__':
    a = Server()
    asyncio.run(a.run())

this part is working as expected (src/example_server.py prints string "server output" every second).

INFO:root:run app
INFO:root:server protocol init
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'
INFO:root:data received: b'server output\n'

when I try to use this with pytest and run from console, subprocess doesn't log anything.

here is my pytest code:

import asyncio
import logging
import pytest

from src.Server import Server

logger = logging.getLogger()


class TestsTest:
    @pytest.mark.asyncio
    async def test_1(self):
        s = Server()
        asyncio.create_task(s.run_app())
        await asyncio.sleep(3)
        logger.info(s.protocol.output)

and the pytest output:

$ sudo pytest tests_tests.py 
============================================================ test session starts =============================================================
platform linux -- Python 3.10.6, pytest-7.4.0, pluggy-1.2.0
rootdir: /home/vagrant/repos/tests/component_tests
configfile: pytest.ini
plugins: asyncio-0.21.1
asyncio: mode=strict
collected 1 item                                                                                                                             

tests_tests.py::TestsTest::test_1 
--------------------------------------------------------------- live log call ----------------------------------------------------------------
[    INFO] run app
[    INFO] date protocol init
[    INFO] bytearray(b'')
PASSED                                                                                                                                 [100%]

============================================================= 1 passed in 3.01s ==============================================================

However when I run test from pycharm it logs properly the output from Server:

/usr/bin/python3.10 /snap/pycharm-community/340/plugins/python-ce/helpers/pycharm/_jb_pytest_runner.py --path /home/vagrant/repos/tests/component_tests/tests_tests.py 
Testing started at 8:55 AM ...
Launching pytest with arguments /home/vagrant/repos/tests/component_tests/tests_tests.py --no-header --no-summary -q in /home/vagrant/repos/tests/component_tests

============================= test session starts ==============================
collecting ... collected 1 item

tests_tests.py::TestsTest::test_1 

============================== 1 passed in 3.01s ===============================

-------------------------------- live log call ---------------------------------
[    INFO] run app
[    INFO] date protocol init
[    INFO] data received: b'server output\n'
[    INFO] data received: b'server output\n'
[    INFO] bytearray(b'server output\nserver output\n')
PASSED                                                                   [100%]
Process finished with exit code 0

I'm positive that in all cases "src/example_server.py" is executed but I don't understand why I don't get the logs from subprocess when using it with pytest started from console. Could you help me figure it out what could be wrong with my code and how to fix it?

asyncio subprocess with pytest does not call pipe_data_received

0 Answers0