pytest-dev / pytest-dev/pytest-xdist

logs appearing twice when using custom logger and xdist

Open
#605 2 comments 2 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 have the following plugin

import logging
import os
import pytest
from shutil import copyfile
from utilities import constants, shared_resources

class OutputHandler(object):
"""
This plugin handles the output captured for each test.
By default it will print all output, separated by stderr, stdout, log, and exceptions.
Optionally, this output can also be written to a file per test.
"""
def init(self, log_to_console=True, log_to_file=False):
self.exceptions = {}
self.log_to_file = log_to_file
self.log_to_console = log_to_console
self.log_formatter = logging.Formatter(
fmt='%(asctime)s %(message)s',
datefmt='%Y-%m-%d %H:%M:%S')

def get_header(self, text):
    return "\n" + " {} ".format(text).center(60, "-")

def get_subheader(self, text):
    return "\n" + " {} ".format(text).center(30, "-")

def get_logger(self, file_path):
    logger = logging.getLogger(file_path)
    logger.setLevel(logging.DEBUG)
    logger.propagate = False

    if self.log_to_console:
        stream_handler = logging.StreamHandler()
        stream_handler.setFormatter(self.log_formatter)
        logger.addHandler(stream_handler)

    if self.log_to_file:
        file_handler = logging.FileHandler(file_path)
        file_handler.setFormatter(self.log_formatter)
        logger.addHandler(file_handler)

    return logger

def pytest_runtest_logreport(self, report):
    """
    This is called 3 times per test, once for each phase: setup/call/teardown
    An exception that happens in one of these phases is only shown in the report for that phase.
    stdout, stderr and log statements are built up and kept through all phases.

    """

    # Don't print anything until all output is done being captured in the final phase
    if report.when == "teardown":

        logs_directory = shared_resources.get_logs_directory()
        file_path = os.path.abspath(os.path.join(logs_directory, report.location[-1]))
        logger = self.get_logger(file_path)
        logger.info("\n{}".format(report.nodeid))

        for report_section_name, report_section_content in report.sections:
            logger.info(self.get_header(report_section_name))
            logger.info(report_section_content)


        # Upload the log file to VSO
        if self.log_to_file:
            # Logger doesn't close file until process ends so VSO can't upload it. Make a copy for VSO.
            copied_file_path = file_path + ".log"
            file_path = copyfile(file_path, copied_file_path)
            print("\n##vso[task.uploadfile]" + copied_file_path + "\n")

        logger.info("\n\n")
        logger.disabled = True

def pytest_addoption(parser):
group = parser.getgroup(constants.plugin_group_name)
group._addoption("--log-to-files", action="store_true", help="log each test to a file")

def pytest_configure(config):
log_to_file = config.getvalue("--log-to-files")
log_to_console = not config.getvalue("--quiet")

if log_to_file or log_to_console:
    config.pluginmanager.register(
        OutputHandler(log_to_console=log_to_console, log_to_file=log_to_file),
        "output_handler")

when I run tests using command
pytest {test path}

all the stdout, stderr from tests are captured and printed to console in teardown stage once as expected.

when I run tests using distributed
pytest -n 3 {test path}

all the stdout and stderr from tests are captured and printed to console twice.

If I replace log.info with print

the console logs only appear once.

Any idea what is causing the duplication?
I tried logger.propogate = False but didnt work

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 shown plugin's get_logger and pytest_runtest_logreport methods, then reproduce the behavior with pytest {test path} and pytest -n 3 {test path}. Compare the output produced through logger.info with print and determine why xdist causes the captured sections to appear twice; done means distributed runs print each section only once.

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.