stdout/stderr/call setup logging missing when running on a separate worker

[marto1]

I ran into a pretty weird issue while getting a test suite running with pytest. It seems xdist would capture (or preserve, not sure) setup logs only if the setup fixture is running on the same worker. Here is a minimal model of my setup:

import os
import sys
import pytest
import logging
import unittest
from time import sleep


logger = logging.getLogger(__name__)
WORK_MASTER = "EMPTY"


def ingest_file(db_schema, file_path, sep="\t"):
    print('Hello world', file=sys.stdout)
    logger.warning("Read csv file...")
    reading_file = sleep(1)
    logger.warning("Table created now")


@pytest.fixture(scope="session", autouse=True)
def setup_session(testrun_uid, worker_id):
    global WORK_MASTER
    if worker_id == "gw0":
        WORK_MASTER = os.environ["PYTEST_XDIST_WORKER"]
        logger.warning("Setting up user api environment on: %s", os.environ["PYTEST_XDIST_WORKER"])
        TEST_DATA_DIR = '/opt/test-data/user_api'
        PROJECT_NAME = 'p0042'

        # Run a test file through the standard ingest flow, so it's
        # accessible to this test case
        ingest_file(f'{PROJECT_NAME}_files', TEST_DATA_DIR, sep="\t")
        logger.warning("we are done here")


class OtherUserAPITest(unittest.TestCase):

    def setUp(self):
        self.oo = object()

    def test_sources2(self):
        # Should return a sorted list of string names of top-level ingested sources
        sleep(2)
        assert 1

    def test_source3(self):
        # Should return a sorted list of string names of top-level ingested sources
        assert 1

    def test_sources9(self):
        # Should return a sorted list of string names of top-level ingested sources
        assert 1

    def test_name(self):
        sleep(10)
        global WORK_MASTER
        logger.warning("What is going on %s ; %s", os.environ["PYTEST_XDIST_WORKER"], WORK_MASTER)
        assert 0

It's not super deterministic, but if you play with if worker_id == "gw0" to if worker_id == "gw1" or vice versa you'll either get:

==================================================================================================================================================================================== test session starts =====================================================================================================================================================================================
platform linux -- Python 3.10.12, pytest-7.4.3, pluggy-1.3.0
rootdir: /home/martin
plugins: xdist-3.5.0
2 workers [4 items]     
..F.                                                                                                                                                                                                                                                                                                                                                                                   [100%]
========================================================================================================================================================================================== FAILURES ==========================================================================================================================================================================================
_________________________________________________________________________________________________________________________________________________________________________________ OtherUserAPITest.test_name _________________________________________________________________________________________________________________________________________________________________________________
[gw0] linux -- Python 3.10.12 /ptest/pyt/bin/python3

self = <test_pytest_stuff.OtherUserAPITest testMethod=test_name>

    def test_name(self):
        sleep(10)
        global WORK_MASTER
        logger.warning("What is going on %s ; %s", os.environ["PYTEST_XDIST_WORKER"], WORK_MASTER)
>       assert 0
E       assert 0

test_pytest_stuff.py:57: AssertionError
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Captured stdout setup ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hello world
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Captured log setup -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
WARNING  test_pytest_stuff:test_pytest_stuff.py:25 Setting up user api environment on: gw0
WARNING  test_pytest_stuff:test_pytest_stuff.py:15 Read csv file...
WARNING  test_pytest_stuff:test_pytest_stuff.py:17 Table created now
WARNING  test_pytest_stuff:test_pytest_stuff.py:32 we are done here
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Captured log call --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
WARNING  test_pytest_stuff:test_pytest_stuff.py:56 What is going on gw0 ; gw0
===================================================================================================================================================================================== slowest durations ======================================================================================================================================================================================
10.00s call     sources/ptest/test_pytest_stuff.py::OtherUserAPITest::test_name
2.00s call     sources/ptest/test_pytest_stuff.py::OtherUserAPITest::test_sources2
1.01s setup    sources/ptest/test_pytest_stuff.py::OtherUserAPITest::test_name

(9 durations < 0.005s hidden.  Use -vv to show these durations.)
================================================================================================================================================================================== short test summary info ===================================================================================================================================================================================
FAILED test_pytest_stuff.py::OtherUserAPITest::test_name - assert 0
================================================================================================================================================================================ 1 failed, 3 passed in 11.54s ================================================================================================================================================================================

Which is what I expect, or:

==================================================================================================================================================================================== test session starts =====================================================================================================================================================================================
platform linux -- Python 3.10.12, pytest-7.4.3, pluggy-1.3.0
rootdir: /home/martin
plugins: xdist-3.5.0
2 workers [4 items]     
..F.                                                                                                                                                                                                                                                                                                                                                                                   [100%]
========================================================================================================================================================================================== FAILURES ==========================================================================================================================================================================================
_________________________________________________________________________________________________________________________________________________________________________________ OtherUserAPITest.test_name _________________________________________________________________________________________________________________________________________________________________________________
[gw0] linux -- Python 3.10.12 /ptest/pyt/bin/python3

self = <test_pytest_stuff.OtherUserAPITest testMethod=test_name>

    def test_name(self):
        sleep(10)
        global WORK_MASTER
        logger.warning("What is going on %s ; %s", os.environ["PYTEST_XDIST_WORKER"], WORK_MASTER)
>       assert 0
E       assert 0

test_pytest_stuff.py:57: AssertionError
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Captured log call --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
WARNING  test_pytest_stuff:test_pytest_stuff.py:56 What is going on gw0 ; EMPTY
===================================================================================================================================================================================== slowest durations ======================================================================================================================================================================================
10.01s call     sources/ptest/test_pytest_stuff.py::OtherUserAPITest::test_name
2.00s call     sources/ptest/test_pytest_stuff.py::OtherUserAPITest::test_sources2
1.01s setup    sources/ptest/test_pytest_stuff.py::OtherUserAPITest::test_sources2

(9 durations < 0.005s hidden.  Use -vv to show these durations.)
================================================================================================================================================================================== short test summary info ===================================================================================================================================================================================
FAILED test_pytest_stuff.py::OtherUserAPITest::test_name - assert 0
================================================================================================================================================================================ 1 failed, 3 passed in 10.59s ================================================================================================================================================================================

if it's running on the other worker. I run like pytest -n 2 --durations=0 test_pytest_stuff.py in both cases. Is this expected behaviour and if so is there a way to always show the setup logs?

[marto1]

Possible duplicate of https://github.com/pytest-dev/pytest-xdist/issues/480 ??

[nicoddemus]

Hi @marto1,

Possibly it is at least related, but I have not looked into it in detail.