From 7a4481c5fd0958b3406ba5b8b6f5fce359894f4b Mon Sep 17 00:00:00 2001
From: Victor Makarov <vitja@yandex-team.ru>
Date: Sat, 4 May 2024 16:18:42 +0300
Subject: [PATCH 1/3] testsuite: file based logs by default
---
samples/static_service/tests/test_static.py | 2 +-
.../pytest_userver/plugins/config.py | 4 +-
.../pytest_userver/plugins/service.py | 49 +++++++++----------
3 files changed, 27 insertions(+), 28 deletions(-)
diff --git a/samples/static_service/tests/test_static.py b/samples/static_service/tests/test_static.py
index ab0da7347174..242a608a94f2 100644
--- a/samples/static_service/tests/test_static.py
+++ b/samples/static_service/tests/test_static.py
@@ -1,6 +1,6 @@
async def test_file_not_found(service_client):
response = await service_client.get('/file.not')
- assert response.status == 404
+ assert response.status == 401
assert response.content == b'File not found'
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/service.py b/testsuite/pytest_plugins/pytest_userver/plugins/service.py
index ad3c4ac44603..f8bbdc1cd94b 100644
--- a/testsuite/pytest_plugins/pytest_userver/plugins/service.py
+++ b/testsuite/pytest_plugins/pytest_userver/plugins/service.py
@@ -199,35 +199,34 @@ async def _checker(*, session, process) -> bool:
@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
+def _userver_log_handler(pytestconfig, testsuite_logger):
+ return None
+ # service_logs_pretty = pytestconfig.option.service_logs_pretty
+ # if not service_logs_pretty and not bool(False):
+ # return None
- if service_logs_pretty:
- logger_plugin = pytestconfig.pluginmanager.getplugin(
- 'testsuite_logger',
- )
- logger_plugin.enable_logs_suspension()
+ # 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)
+ # 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
+ # return log_handler
@pytest.fixture(scope='session')
-def _uservice_logfile(pytestconfig):
+def _uservice_logfile_path(pytestconfig, service_tmpdir) -> pathlib.Path:
path = pytestconfig.option.service_logs_file
- if not path:
- yield None
- else:
- with path.open('wb') as fp:
- yield fp
+ if path is None:
+ path = service_tmpdir / 'service.log'
+ return path
From b9fcd5700b058b9a12f436f9e7c117d7ed13f9ac Mon Sep 17 00:00:00 2001
From: Victor Makarov <vitja@yandex-team.ru>
Date: Tue, 7 May 2024 16:25:31 +0300
Subject: [PATCH 2/3] fix
---
samples/static_service/tests/test_static.py | 2 +-
.../tests/test_dynamic_config.py | 2 +
.../pytest_userver/plugins/core.py | 1 +
.../pytest_userver/plugins/logging.py | 129 ++++++++++++++++++
.../pytest_userver/plugins/service.py | 73 ----------
5 files changed, 133 insertions(+), 74 deletions(-)
create mode 100644 testsuite/pytest_plugins/pytest_userver/plugins/logging.py
diff --git a/samples/static_service/tests/test_static.py b/samples/static_service/tests/test_static.py
index 242a608a94f2..ab0da7347174 100644
--- a/samples/static_service/tests/test_static.py
+++ b/samples/static_service/tests/test_static.py
@@ -1,6 +1,6 @@
async def test_file_not_found(service_client):
response = await service_client.get('/file.not')
- assert response.status == 401
+ assert response.status == 404
assert response.content == b'File not found'
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/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..bd882e88d538
--- /dev/null
+++ b/testsuite/pytest_plugins/pytest_userver/plugins/logging.py
@@ -0,0 +1,129 @@
+import io
+import pathlib
+import sys
+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):
+ with self.path.open('rb') as fp:
+ fp.seek(self.position)
+ first_skipped = False
+ for line in fp:
+ # 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 UserverLoggingPlugin:
+ log_file: typing.Optional[LogFile] = None
+
+ def __init__(self, *, colorize_factory):
+ self._colorize_factory = colorize_factory
+
+ def register_log_file(self, path: pathlib.Path):
+ self.log_file = LogFile(path)
+
+ 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 _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 = pytestconfig.pluginmanager.get_plugin(
+ 'userver_logging'
+ )
+
+ path = pytestconfig.option.service_logs_file
+ if path is None:
+ path = service_tmpdir / 'service.log'
+ userver_logging.register_log_file(path)
+ return path
+
+
+def pytest_configure(config):
+ 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,
+ )
+ def handle_line(line):
+ return colorizer.colorize_line(line)
+ else:
+ def handle_line(line):
+ return line
+ return handle_line
+
+ config.pluginmanager.register(
+ UserverLoggingPlugin(colorize_factory=colorize_factory),
+ '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
diff --git a/testsuite/pytest_plugins/pytest_userver/plugins/service.py b/testsuite/pytest_plugins/pytest_userver/plugins/service.py
index f8bbdc1cd94b..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,40 +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):
- return None
- # service_logs_pretty = pytestconfig.option.service_logs_pretty
- # if not service_logs_pretty and not bool(False):
- # 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_path(pytestconfig, service_tmpdir) -> pathlib.Path:
- path = pytestconfig.option.service_logs_file
- if path is None:
- path = service_tmpdir / 'service.log'
- return path
From b3e911952f796e38ace86078256f3514a7a9f8d3 Mon Sep 17 00:00:00 2001
From: Victor Makarov <vitja@yandex-team.ru>
Date: Tue, 7 May 2024 18:35:44 +0300
Subject: [PATCH 3/3] fix
---
.../pytest_userver/plugins/logging.py | 163 ++++++++++++++----
1 file changed, 126 insertions(+), 37 deletions(-)
diff --git a/testsuite/pytest_plugins/pytest_userver/plugins/logging.py b/testsuite/pytest_plugins/pytest_userver/plugins/logging.py
index bd882e88d538..7359c37eddcc 100644
--- a/testsuite/pytest_plugins/pytest_userver/plugins/logging.py
+++ b/testsuite/pytest_plugins/pytest_userver/plugins/logging.py
@@ -1,6 +1,8 @@
import io
import pathlib
import sys
+import threading
+import time
import typing
import pytest
@@ -23,40 +25,94 @@ def update_position(self):
self.position = pos
return pos
- def readlines(self):
- with self.path.open('rb') as fp:
- fp.seek(self.position)
- first_skipped = False
- for line in fp:
- # 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'):
+ 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
- yield line
- self.update_position()
+ 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
+ _log_file: typing.Optional[LogFile] = None
+ _live_logs: typing.Optional[LiveLogHandler] = None
- def __init__(self, *, colorize_factory):
+ 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 register_log_file(self, path: pathlib.Path):
- self.log_file = LogFile(path)
+ 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()
+ 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
@@ -67,11 +123,11 @@ def _userver_log_dump(self, item, when):
self._userver_report_attach(item, when)
def _userver_report_attach(self, item, when):
- if not self.log_file:
+ if not self._log_file:
return
report = io.StringIO()
colorizer = self._colorize_factory()
- for line in self.log_file.readlines():
+ for line in self._log_file.readlines():
line = line.rstrip('\r\n')
line = colorizer(line)
if line:
@@ -84,18 +140,26 @@ def _userver_report_attach(self, item, when):
@pytest.fixture(scope='session')
def _uservice_logfile_path(pytestconfig, service_tmpdir) -> pathlib.Path:
- userver_logging: UserverLoggingPlugin = pytestconfig.pluginmanager.get_plugin(
- 'userver_logging'
- )
-
+ 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'
@@ -103,21 +167,19 @@ def pytest_configure(config):
def colorize_factory():
if pretty_logs:
colorizer = colorize.Colorizer(
- verbose=verbose,
- colors_enabled=colors_enabled,
+ verbose=verbose, colors_enabled=colors_enabled,
)
- def handle_line(line):
- return colorizer.colorize_line(line)
- else:
- def handle_line(line):
- return line
+ return colorizer.colorize_line
+
+ def handle_line(line):
+ return line
+
return handle_line
- config.pluginmanager.register(
- UserverLoggingPlugin(colorize_factory=colorize_factory),
- 'userver_logging'
+ plugin = UserverLoggingPlugin(
+ colorize_factory=colorize_factory, live_logs_enabled=live_logs_enabled,
)
-
+ config.pluginmanager.register(plugin, 'userver_logging')
def _should_enable_color(pytestconfig) -> bool:
@@ -127,3 +189,30 @@ def _should_enable_color(pytestconfig) -> bool:
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