diff --git a/samples/testsuite-support/tests/test_dynamic_config.py b/samples/testsuite-support/tests/test_dynamic_config.py index eeb5f000a040..5c9764b5e87f 100644 --- a/samples/testsuite-support/tests/test_dynamic_config.py +++ b/samples/testsuite-support/tests/test_dynamic_config.py @@ -25,6 +25,8 @@ async def test_set_values(service_client, dynamic_config): # automatically from the 'dynamic_config' fixture to the service. assert await get_service_config_value(service_client) == CUSTOM_VALUE + assert False + dynamic_config.set_values({TEST_CONFIG: SPECIAL_VALUE}) assert dynamic_config.get(TEST_CONFIG) == SPECIAL_VALUE # The config values changed again, so they are automatically synchronized diff --git a/testsuite/pytest_plugins/pytest_userver/plugins/config.py b/testsuite/pytest_plugins/pytest_userver/plugins/config.py index cc2fda1eb06d..c150fd01ee82 100644 --- a/testsuite/pytest_plugins/pytest_userver/plugins/config.py +++ b/testsuite/pytest_plugins/pytest_userver/plugins/config.py @@ -426,7 +426,7 @@ def userver_log_level(pytestconfig, userver_default_log_level) -> str: @pytest.fixture(scope='session') -def userver_config_logging(userver_log_level): +def userver_config_logging(userver_log_level, _uservice_logfile_path): """ Returns a function that adjusts the static configuration file for testsuite. Sets the `logging.loggers.default` to log to `@stderr` with level set @@ -440,7 +440,7 @@ def _patch_config(config_yaml, config_vars): if 'logging' in components: components['logging']['loggers'] = { 'default': { - 'file_path': '@stderr', + 'file_path': str(_uservice_logfile_path), 'level': userver_log_level, 'overflow_behavior': 'discard', }, diff --git a/testsuite/pytest_plugins/pytest_userver/plugins/core.py b/testsuite/pytest_plugins/pytest_userver/plugins/core.py index ef7d36933390..fb3573faa05c 100644 --- a/testsuite/pytest_plugins/pytest_userver/plugins/core.py +++ b/testsuite/pytest_plugins/pytest_userver/plugins/core.py @@ -14,6 +14,7 @@ 'pytest_userver.plugins.dumps', 'pytest_userver.plugins.dynamic_config', 'pytest_userver.plugins.log_capture', + 'pytest_userver.plugins.logging', 'pytest_userver.plugins.service', 'pytest_userver.plugins.service_client', 'pytest_userver.plugins.service_runner', diff --git a/testsuite/pytest_plugins/pytest_userver/plugins/logging.py b/testsuite/pytest_plugins/pytest_userver/plugins/logging.py new file mode 100644 index 000000000000..7359c37eddcc --- /dev/null +++ b/testsuite/pytest_plugins/pytest_userver/plugins/logging.py @@ -0,0 +1,218 @@ +import io +import pathlib +import sys +import threading +import time +import typing + +import pytest + +from ..utils import colorize + + +class LogFile: + def __init__(self, path: pathlib.Path): + self.path = path + self.update_position() + + def update_position(self): + try: + st = self.path.stat() + except FileNotFoundError: + pos = 0 + else: + pos = st.st_size + self.position = pos + return pos + + def readlines( + self, + eof_handler: typing.Optional[typing.Callable[[], bool]] = None, + ): + first_skipped = False + for line in _raw_line_reader( + self.path, self.position, eof_handler=eof_handler, + ): + # userver does not give any gurantees about log file encoding + line = line.decode(encoding='utf-8', errors='ignore') + if not first_skipped: + first_skipped = True + if not line.startswith('tskv '): + continue + if not line.endswith('\n'): + continue + yield line + self.update_position() + + +class LiveLogHandler: + def __init__(self, *, colorize_factory, delay: float = 0.05): + self._colorize_factory = colorize_factory + self._threads = {} + self._exiting = False + self._delay = delay + + def register_log_file(self, path: pathlib.Path): + if path in self._threads: + return + thread = threading.Thread(target=self._logreader_thread, args=(path,)) + self._threads[path] = thread + thread.start() + + def join(self, timeout: float = 10): + self._exiting = True + for thread in self._threads.values(): + thread.join(timeout=timeout) + + def _logreader_thread(self, path: pathlib.Path): + # wait for file to appear + while not path.exists(): + if self._eof_handler(): + return + colorizer = self._colorize_factory() + log_file = LogFile(path) + for line in log_file.readlines(eof_handler=self._eof_handler): + line = line.rstrip('\r\n') + line = colorizer(line) + if line: + self._write_logline(line) + + def _write_logline(self, line: str): + print(line, file=sys.stderr) + + def _eof_handler(self) -> bool: + if self._exiting: + return True + time.sleep(self._delay) + return False + + +class UserverLoggingPlugin: + _log_file: typing.Optional[LogFile] = None + _live_logs: typing.Optional[LiveLogHandler] = None + + def __init__(self, *, colorize_factory, live_logs_enabled: bool = False): + self._colorize_factory = colorize_factory + if live_logs_enabled: + self._live_logs = LiveLogHandler(colorize_factory=colorize_factory) + + def pytest_sessionfinish(self, session): + if self._live_logs: + self._live_logs.join() + + def pytest_runtest_setup(self, item): + if self._log_file: + self._log_file.update_position() + + @pytest.hookimpl(wrapper=True) + def pytest_runtest_teardown(self, item): + yield from self._userver_log_dump(item, 'teardown') + + def register_log_file(self, path: pathlib.Path): + self._log_file = LogFile(path) + if self._live_logs: + self._live_logs.register_log_file(path) + + def _userver_log_dump(self, item, when): + try: + yield + except Exception: + self._userver_report_attach(item, when) + raise + if item.utestsuite_report.failed: + self._userver_report_attach(item, when) + + def _userver_report_attach(self, item, when): + if not self._log_file: + return + report = io.StringIO() + colorizer = self._colorize_factory() + for line in self._log_file.readlines(): + line = line.rstrip('\r\n') + line = colorizer(line) + if line: + report.write(line) + report.write('\n') + value = report.getvalue() + if value: + item.add_report_section(when, 'userver/log', value) + + +@pytest.fixture(scope='session') +def _uservice_logfile_path(pytestconfig, service_tmpdir) -> pathlib.Path: + userver_logging: UserverLoggingPlugin + userver_logging = pytestconfig.pluginmanager.get_plugin('userver_logging') + path = pytestconfig.option.service_logs_file + if path is None: + path = service_tmpdir / 'service.log' + with open(path, 'w+') as fp: + fp.truncate() + userver_logging.register_log_file(path) + return path + + +def pytest_configure(config): + if config.option.capture == 'no' and config.option.showcapture in ( + 'all', + 'log', + ): + live_logs_enabled = True + else: + live_logs_enabled = False + + pretty_logs = config.option.service_logs_pretty + colors_enabled = _should_enable_color(config) + verbose = pretty_logs == 'verbose' + + def colorize_factory(): + if pretty_logs: + colorizer = colorize.Colorizer( + verbose=verbose, colors_enabled=colors_enabled, + ) + return colorizer.colorize_line + + def handle_line(line): + return line + + return handle_line + + plugin = UserverLoggingPlugin( + colorize_factory=colorize_factory, live_logs_enabled=live_logs_enabled, + ) + config.pluginmanager.register(plugin, 'userver_logging') + + +def _should_enable_color(pytestconfig) -> bool: + option = getattr(pytestconfig.option, 'color', 'no') + if option == 'yes': + return True + if option == 'auto': + return sys.stderr.isatty() + return False + + +def _raw_line_reader( + path: pathlib.Path, + position: int = 0, + eof_handler: typing.Optional[typing.Callable[[], bool]] = None, + bufsize: int = 16384, +): + buf = b'' + with path.open('rb') as fp: + fp.seek(position) + while True: + chunk = fp.read(bufsize) + if not chunk: + if not eof_handler: + break + if eof_handler(): + break + else: + buf += chunk + lines = buf.splitlines(keepends=True) + if not lines[-1].endswith(b'\n'): + buf = lines[-1] + del lines[-1] + else: + buf = b'' + yield from lines diff --git a/testsuite/pytest_plugins/pytest_userver/plugins/service.py b/testsuite/pytest_plugins/pytest_userver/plugins/service.py index ad3c4ac44603..e9227a648514 100644 --- a/testsuite/pytest_plugins/pytest_userver/plugins/service.py +++ b/testsuite/pytest_plugins/pytest_userver/plugins/service.py @@ -5,43 +5,19 @@ # pylint: disable=redefined-outer-name import logging import pathlib -import sys import time -import traceback import typing import pytest -from testsuite.logging import logger from testsuite.utils import url_util -from ..utils import colorize from ..utils import net logger_testsuite = logging.getLogger(__name__) -class ColorLogger(logger.Logger): - def __init__( - self, *, writer: logger.LineLogger, verbose, colors_enabled, - ) -> None: - super().__init__(writer) - self._colorizer = colorize.Colorizer( - verbose=verbose, colors_enabled=colors_enabled, - ) - - def log_service_line(self, line) -> None: - line = self._colorizer.colorize_line(line) - if line: - self.writeline(line) - - def log_entry(self, entry: dict) -> None: - line = self._colorizer.colorize_row(entry) - if line: - self.writeline(line) - - def pytest_addoption(parser) -> None: group = parser.getgroup('userver') group.addoption( @@ -69,19 +45,6 @@ def pytest_addoption(parser) -> None: ) -def pytest_override_testsuite_logger( # pylint: disable=invalid-name - config, line_logger: logger.LineLogger, colors_enabled: bool, -) -> typing.Optional[logger.Logger]: - pretty_logs = config.option.service_logs_pretty - if not pretty_logs: - return None - return ColorLogger( - writer=line_logger, - verbose=pretty_logs == 'verbose', - colors_enabled=colors_enabled, - ) - - @pytest.fixture(scope='session') def service_env(): """ @@ -143,7 +106,6 @@ async def service_daemon( service_binary, service_non_http_health_checks, testsuite_logger, - _userver_log_handler, ): """ Configures the health checking to use service_http_ping_url fixture value @@ -193,41 +155,5 @@ async def _checker(*, session, process) -> bool: ping_url=service_http_ping_url, health_check=health_check, env=service_env, - stderr_handler=_userver_log_handler, ) as scope: yield scope - - -@pytest.fixture(scope='session') -def _userver_log_handler(pytestconfig, testsuite_logger, _uservice_logfile): - service_logs_pretty = pytestconfig.option.service_logs_pretty - if not service_logs_pretty and not bool(_uservice_logfile): - return None - - if service_logs_pretty: - logger_plugin = pytestconfig.pluginmanager.getplugin( - 'testsuite_logger', - ) - logger_plugin.enable_logs_suspension() - - def log_handler(line_binary): - if _uservice_logfile: - _uservice_logfile.write(line_binary) - try: - line = line_binary.decode('utf-8').rstrip('\r\n') - testsuite_logger.log_service_line(line) - # flake8: noqa - except: - traceback.print_exc(file=sys.stderr) - - return log_handler - - -@pytest.fixture(scope='session') -def _uservice_logfile(pytestconfig): - path = pytestconfig.option.service_logs_file - if not path: - yield None - else: - with path.open('wb') as fp: - yield fp