pytest-dev / pytest-dev/pytest-xdist

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

Open
#980 2 comments 0 reactions 0 assignees View on GitHub

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

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.