Improve logging and separate it per-test (2eb7552c) · Commits · David Auer / gekkofs

tests/conftest.py

+35 −10

Original line number	Diff line number	Diff line
		@@ -11,15 +11,30 @@
		# SPDX-License-Identifier: MIT #
		################################################################################

		import os, sys
		import pytest
		import logging
		from collections import namedtuple
		from _pytest.logging import caplog as _caplog
		from pathlib import Path
		from harness.logger import logger
		from harness.cli import add_cli_options
		from harness.logger import logger, initialize_logging, finalize_logging
		from harness.cli import add_cli_options, set_default_log_formatter
		from harness.workspace import Workspace, FileCreator
		from harness.gkfs import Daemon, Client, ShellClient
		from harness.reporter import report_test_status, report_test_headline, report_assertion_pass

		def pytest_configure(config):
		"""
		Some configurations for our particular usage of pytest
		"""
		set_default_log_formatter(config, "%(message)s")

		def pytest_assertion_pass(item, lineno, orig, expl):

		location = namedtuple(
		'Location', ['path', 'module', 'function', 'lineno'])(
		str(item.parent.fspath), item.parent.name, item.name, lineno)

		report_assertion_pass(logger, location, orig, expl)

		def pytest_addoption(parser):
		"""
		@@ -28,21 +43,31 @@ def pytest_addoption(parser):
		add_cli_options(parser)

		@pytest.fixture(autouse=True)
		def caplog(_caplog):
		def caplog(test_workspace, request, _caplog):

		# we don't need to see the logs from sh
		_caplog.set_level(logging.CRITICAL, 'sh.command')
		_caplog.set_level(logging.CRITICAL, 'sh.command.process')
		_caplog.set_level(logging.CRITICAL, 'sh.command.process.streamreader')
		_caplog.set_level(logging.CRITICAL, 'sh.stream_bufferer')
		_caplog.set_level(logging.CRITICAL, 'sh.streamreader')

		class PropagateHandler(logging.Handler):
		def emit(self, record):
		logging.getLogger(record.name).handle(record)
		test_log_path = test_workspace.logdir / (request.node.name + ".log")

		h = initialize_logging(logger, test_log_path)
		report_test_headline(logger, request.node.nodeid, request.config)

		handler_id = logger.add(PropagateHandler(), format="{message}")
		yield _caplog
		logger.remove(handler_id)

		finalize_logging(logger, h)

		def pytest_runtest_logreport(report):
		"""
		Pytest hook called after a test phase (setup, call, teardownd)
		has completed.
		"""

		report_test_status(logger, report)

		@pytest.fixture
		def test_workspace(tmp_path, request):
		@@ -50,7 +75,7 @@ def test_workspace(tmp_path, request):
		Initializes a test workspace by creating a temporary directory for it.
		"""

		return Workspace(tmp_path,
		yield Workspace(tmp_path,
		request.config.getoption('--bin-dir'),
		request.config.getoption('--lib-dir'))

tests/conftest.py.in

+7 −1

Original line number	Diff line number	Diff line
		@@ -11,9 +11,15 @@
		# SPDX-License-Identifier: MIT #
		################################################################################

		from harness.cli import add_cli_options
		from harness.cli import add_cli_options, set_default_log_formatter
		from pathlib import Path

		def pytest_configure(config):
		"""
		Some configurations for our particularusage of pytest
		"""
		set_default_log_formatter(config, "%(message)s")

		def pytest_addoption(parser):
		"""
		Adds extra options from the GKFS harness to the py.test CLI.

tests/harness/cli.py

+28 −0

Original line number	Diff line number	Diff line
		@@ -11,6 +11,8 @@
		# SPDX-License-Identifier: MIT #
		################################################################################

		import _pytest
		import logging
		from pathlib import Path

		### This code is meant to be included automatically by CMake in the build
		@@ -51,3 +53,29 @@ def add_cli_options(parser):
		# from the build directory's conftest.py and from the source
		# directory's conftest.py through automatic finding, ignore the error
		pass


		def set_default_log_formatter(config, fmt):

		plugin_class = config.pluginmanager.get_plugin('logging').LoggingPlugin

		if not isinstance(plugin_class, LoggingPlugin):
		config.pluginmanager.get_plugin('logging').LoggingPlugin = LoggingPlugin


		class LoggingPlugin(_pytest.logging.LoggingPlugin):
		"""
		Replacement logging plugin that rewrites py.test default log formatter
		"""

		def _create_formatter(self, log_format,
		log_date_format, auto_indent) -> logging.Formatter:
		"""
		Patch pytest default logger to always return our formatter

		Returns:
		logging.Formatter: Our formatter
		"""

		# since we use loguru for formatting, we just want the message
		return logging.Formatter("%(message)s")

tests/harness/logger.py

+99 −0

Original line number	Diff line number	Diff line
		@@ -11,4 +11,103 @@
		# SPDX-License-Identifier: MIT #
		################################################################################

		import re
		import logging
		from loguru import logger

		class LogFormatter:
		"""
		Formatter class for our log messages
		"""

		def __init__(self, colorize=True):
		self._colorize = colorize

		# color
		self._prefix_fmt = "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> \| <level>{level: <8}</level> \| <cyan>{name}</cyan>:<cyan>{line}</cyan> \| "
		self._suffix_fmt = "<level>{message}</level>\n"

		# raw
		self._raw_prefix_fmt = "{time:YYYY-MM-DD HH:mm:ss.SSS} \| {level: <8} \| {name}:{line} \| "
		self._raw_suffix_fmt = "{extra[raw_message]}\n"

		if colorize:
		self._short_fmt = self._suffix_fmt
		self._fmt = self._prefix_fmt + self._suffix_fmt
		else:
		self._short_fmt = self._raw_suffix_fmt
		self._fmt = self._raw_prefix_fmt + self._raw_suffix_fmt


		def format(self, record):

		def _ansi_strip(msg):
		# 7-bit C1 ANSI sequences
		ansi_escape = re.compile(r'''
		\x1B # ESC
		(?: # 7-bit C1 Fe (except CSI)
		[@-Z\\-_]
		\| # or [ for CSI, followed by a control sequence
		\[
		[0-?]* # Parameter bytes
		[ -/]* # Intermediate bytes
		[@-~] # Final byte
		)
		''', re.VERBOSE)
		return ansi_escape.sub('', msg)

		if not self._colorize:
		record["extra"]["raw_message"] = _ansi_strip(record["message"])

		patch_location = record["extra"].get("patch_location", None)
		if patch_location:
		record.update(file="foobar")

		if record["extra"].get("skip_prefix", False):
		return self._short_fmt

		return self._fmt

		class PropagateHandler(logging.Handler):
		"""
		This class ensures that loguru messages are propagated to caplog
		"""
		def emit(self, record):
		logging.getLogger(record.name).handle(record)


		def initialize_logging(logger, test_log_path, propagate=False):

		handles = []

		# remove loguru's default logger
		logger.remove()

		# create loggers:
		# 1. log to file with ansi color codes
		h0 = logger.add(
		test_log_path.with_suffix(".color.log"),
		colorize=True,
		format=LogFormatter().format)
		handles.append(h0)

		# 2. log to file with plain text
		h1 = logger.add(test_log_path,
		colorize=False,
		format=LogFormatter(False).format)
		handles.append(h1)

		# 3. log propagator to pytest
		if propagate:
		h2 = logger.add(
		PropagateHandler(),
		colorize=True,
		format=LogFormatter().format)
		handles.append(h2)

		return handles

		def finalize_logging(logger, handles):

		for h in handles:
		logger.remove(h)

tests/harness/reporter.py

0 → 100644

+146 −0

Original line number	Diff line number	Diff line
		################################################################################
		# Copyright 2018-2020, Barcelona Supercomputing Center (BSC), Spain #
		# Copyright 2015-2020, Johannes Gutenberg Universitaet Mainz, Germany #
		# #
		# This software was partially supported by the #
		# EC H2020 funded project NEXTGenIO (Project ID: 671951, www.nextgenio.eu). #
		# #
		# This software was partially supported by the #
		# ADA-FS project under the SPPEXA project funded by the DFG. #
		# #
		# SPDX-License-Identifier: MIT #
		################################################################################

		import sys, pytest, pluggy, py, platform
		from collections import namedtuple
		from pathlib import Path
		from pprint import pformat

		report_width = 80

		def _add_sep(sepchar, msg, sepcolor=None, msgcolor=None, fullwidth = report_width):
		# we want 2 + 2*len(fill) + len(msg) <= fullwidth
		# i.e. 2 + 2len(sepchar)N + len(msg) <= fullwidth
		# 2len(sepchar)N <= fullwidth - len(msg) - 2
		# N <= (fullwidth - len(msg) - 2) // (2*len(sepchar))
		N = max((fullwidth - len(msg) - 2) // (2*len(sepchar)), 1)
		fill = sepchar * N

		if sepcolor is not None:
		fill = f"<{sepcolor}>{fill}</>"

		if msgcolor is not None:
		msg = f"<{msgcolor}>{msg}</>"
		line = "%s %s %s" % (fill, msg, fill)

		if len(line) + len(sepchar.rstrip()) <= fullwidth:
		line += sepchar.rstrip()

		return line

		def _format_exception(report):

		if not report.failed:
		return ""

		tw = py.io.TerminalWriter(file=None, stringio=True)
		tw.hasmarkup = True
		tw.fullwidth = report_width
		report.toterminal(tw)

		return tw._file.getvalue()

		def report_test_headline(logger, testid, config):
		"""
		Emit a log message describing a test configuration
		"""

		lg = logger.bind(skip_prefix=True).opt(depth=1, colors=True)

		lg.info(_add_sep("=", "Test session starts"))

		verinfo = platform.python_version()
		msg = "platform {} -- Python {}".format(sys.platform, verinfo)
		pypy_version_info = getattr(sys, "pypy_version_info", None)
		if pypy_version_info:
		verinfo = ".".join(map(str, pypy_version_info[:3]))
		msg += "[pypy-{}-{}]".format(verinfo, pypy_version_info[3])
		msg += ", pytest-{}, py-{}, pluggy-{}".format(
		pytest.__version__, py.__version__, pluggy.__version__
		)

		lg.info(f"<normal>{msg}</>")

		msg = "rootdir: %s" % config.rootdir

		if config.inifile:
		msg += ", inifile: " + config.rootdir.bestrelpath(config.inifile)

		testpaths = config.getini("testpaths")
		if testpaths and config.args == testpaths:
		rel_paths = [config.rootdir.bestrelpath(x) for x in testpaths]
		msg += ", testpaths: {}".format(", ".join(rel_paths))

		lg.info(f"<normal>{msg}</>")
		lg.info(f"\n<yellow>{_add_sep('=', testid)}</>\n")

		def report_test_status(logger, report):
		"""
		Emit a log message describing a test report
		"""

		lg_opts = logger.opt(colors=True).bind(skip_prefix=True)

		def get_phase(report):
		if report.when == "setup":
		return "SETUP"
		elif report.when == "call":
		return "TEST"
		elif report.when == "teardown":
		return "TEARDOWN"
		else:
		raise ValueError("Test report has unknown phase")

		def get_status(report):
		TestReport = namedtuple(
		'TestReport', ['phase', 'color', 'status', 'logfun'])

		phase = get_phase(report)
		was_xfail = hasattr(report, "wasxfail")

		if report.passed and not was_xfail:
		return TestReport(phase, "green", "PASSED", lg_opts.info)
		elif report.passed and was_xfail:
		return TestReport(phase, "yellow", "PASSED", lg_opts.warning)
		elif report.failed:
		return TestReport(phase, "red", "FAILED", lg_opts.error)
		elif report.skipped:
		return TestReport(phase, "yellow", "SKIPPED", lg_opts.warning)
		else:
		raise ValueError("Test report has unknown state")


		phase, color, status, log_fun = get_status(report)
		msg = _add_sep("=", f"{phase} {status}")
		log_fun(f"\n<{color}>{msg}</>\n")

		if report.failed:
		location = f"{_add_sep('_', report.location[2])}"
		exception = _format_exception(report)
		lg_opts.info(f"<normal>{location}\n{{}}</>", exception)
		log_fun(f"{'=' * report_width}")

		def report_assertion_pass(logger, location, orig, expl):

		def patch_record(r):
		copy = r.copy()
		copy["file"].name = Path(location.path).name
		copy["file"].path = location.path
		copy["function"] = location.function
		copy["line"] = location.lineno
		#copy["module"] = location.module
		copy["name"] = Path(location.path).stem
		r.update(copy)

		logger.patch(lambda r : patch_record(r)).info(
		f"assertion \"{orig}\" passed")