pytest-dev / pytest-dev/pytest-xdist
stdout/stderr/call setup logging missing when running on a separate worker
Nobody has claimed this yet.
- Dominant language
- Python
- Stars
- 1.9k
- Forks
- 287
- Avg merge
- 9h 30m
- Merged PRs (30d)
- 2
Description
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?
Contributor guide
No contributing guide indexed for this repository
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with the minimal reproduction in test_pytest_stuff.py and run pytest -n 2 --durations=0 test_pytest_stuff.py, comparing setup output when the fixture runs on gw0 versus another worker. Trace how pytest-xdist reports setup stdout and logs for failures, then determine whether setup logs can be consistently included in the reported failure output.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- distributed-systems, testing
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100