pytest-dev / pytest-dev/pytest-xdist
logs appearing twice when using custom logger and xdist
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
- 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 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