From 983ec58d1858e46a47c2234868a4d1bd5e4174b0 Mon Sep 17 00:00:00 2001 From: phlax Date: Tue, 11 Jan 2022 09:02:16 +0000 Subject: [PATCH] envoy.base.runner: Fix verbosity and logging (#166) Signed-off-by: Ryan Northey --- README.md | 2 +- envoy.base.runner/VERSION | 2 +- .../envoy/base/runner/__init__.py | 6 +- envoy.base.runner/envoy/base/runner/runner.py | 112 ++++-- envoy.base.runner/tests/test_abstract.py | 3 + envoy.base.runner/tests/test_runner.py | 332 ++++++++++++++---- 6 files changed, 354 insertions(+), 103 deletions(-) diff --git a/README.md b/README.md index 238c5ab0e..0ebd60346 100644 --- a/README.md +++ b/README.md @@ -109,7 +109,7 @@ pypi: https://pypi.org/project/envoy.base.checker #### [envoy.base.runner](envoy.base.runner) -version: 0.0.5.dev0 +version: 0.1.0 pypi: https://pypi.org/project/envoy.base.runner diff --git a/envoy.base.runner/VERSION b/envoy.base.runner/VERSION index ccf3e968d..6e8bf73aa 100644 --- a/envoy.base.runner/VERSION +++ b/envoy.base.runner/VERSION @@ -1 +1 @@ -0.0.5-dev +0.1.0 diff --git a/envoy.base.runner/envoy/base/runner/__init__.py b/envoy.base.runner/envoy/base/runner/__init__.py index 8ea79c5c1..0226166ef 100644 --- a/envoy.base.runner/envoy/base/runner/__init__.py +++ b/envoy.base.runner/envoy/base/runner/__init__.py @@ -1,10 +1,9 @@ +from . import runner from .decorators import ( catches, cleansup) - from .abstract import AAsyncRunnerWithCommands - from .runner import ( AsyncRunner, BaseRunner, @@ -27,4 +26,5 @@ "cleansup", "ForkingAdapter", "ForkingRunner", - "Runner") + "Runner", + "runner") diff --git a/envoy.base.runner/envoy/base/runner/runner.py b/envoy.base.runner/envoy/base/runner/runner.py index c6752d3d8..891362ebb 100644 --- a/envoy.base.runner/envoy/base/runner/runner.py +++ b/envoy.base.runner/envoy/base/runner/runner.py @@ -45,13 +45,29 @@ class BazelRunError(Exception): pass +class BaseLogFilter(logging.Filter): + + def __init__(self, app_logger: logging.Logger, *args, **kwargs) -> None: + self.app_logger = app_logger + + +class AppLogFilter(BaseLogFilter): + + def filter(self, record) -> bool: + return record.name == self.app_logger.name + + +class RootLogFilter(BaseLogFilter): + + def filter(self, record) -> bool: + return record.name != self.app_logger.name + + class BaseRunner: def __init__(self, *args): self._args = args - - def __call__(self): - return self.run() + self.setup_logging() @cached_property def args(self) -> argparse.Namespace: @@ -63,38 +79,36 @@ def extra_args(self) -> list: """Unparsed args.""" return self.parser.parse_known_args(self._args)[1] - @property - def log_field_styles(self): - return LOG_FIELD_STYLES - - @property - def log_fmt(self): - return LOG_FMT - - @property - def log_level_styles(self): - return LOG_LEVEL_STYLES - @cached_property def log(self) -> verboselogs.VerboseLogger: """Instantiated logger.""" - verboselogs.install() - logger = logging.getLogger(self.name) - logger.setLevel(self.log_level) + app_logger = verboselogs.VerboseLogger(self.name) coloredlogs.install( field_styles=self.log_field_styles, level_styles=self.log_level_styles, fmt=self.log_fmt, - level='DEBUG', - logger=logger, + level=self.verbosity, + logger=app_logger, isatty=True) - return logger + return app_logger + + @property + def log_field_styles(self): + return LOG_FIELD_STYLES + + @property + def log_fmt(self): + return LOG_FMT @cached_property def log_level(self) -> int: """Log level parsed from args.""" return dict(LOG_LEVELS)[self.args.log_level] + @property + def log_level_styles(self): + return LOG_LEVEL_STYLES + @property def name(self) -> str: """Name of the runner.""" @@ -111,6 +125,27 @@ def parser(self) -> argparse.ArgumentParser: def path(self) -> pathlib.Path: return pathlib.Path(".") + @property + def root_log_format(self) -> logging.Formatter: + return logging.Formatter("%(name)s: %(levelname)s %(message)s") + + @cached_property + def root_log_handler(self) -> logging.Handler: + """Instantiated logger.""" + root_handler = logging.StreamHandler() + root_handler.setLevel(self.log_level) + root_handler.addFilter(RootLogFilter(self.log)) + root_handler.setFormatter(self.root_log_format) + return root_handler + + @cached_property + def root_logger(self) -> logging.Logger: + """Instantiated logger.""" + root_logger = logging.getLogger() + root_logger.handlers[0].addFilter(AppLogFilter(self.log)) + root_logger.addHandler(self.root_log_handler) + return root_logger + @cached_property def stdout(self) -> logging.Logger: """Log to stdout.""" @@ -134,14 +169,10 @@ def tempdir(self) -> tempfile.TemporaryDirectory: "decorated with `@runner.cleansup`") return tempfile.TemporaryDirectory() - def add_arguments(self, parser: argparse.ArgumentParser) -> None: - """Override this method to add custom arguments to the arg parser.""" - parser.add_argument( - "--log-level", - "-l", - choices=[level[0] for level in LOG_LEVELS], - default="info", - help="Log level to display") + @cached_property + def verbosity(self) -> int: + """Log level parsed from args.""" + return dict(LOG_LEVELS)[self.args.verbosity] @property def _missing_cleanup(self) -> bool: @@ -152,6 +183,26 @@ def _missing_cleanup(self) -> bool: getattr(run_fun, "__wrapped__", object()), "__cleansup__", False)) + def add_arguments(self, parser: argparse.ArgumentParser) -> None: + """Override this method to add custom arguments to the arg parser.""" + parser.add_argument( + "--verbosity", + "-v", + choices=[level[0] for level in LOG_LEVELS], + default="info", + help="Application log level") + parser.add_argument( + "--log-level", + "-l", + choices=[level[0] for level in LOG_LEVELS], + default="warn", + help="Log level for non-application logs") + + def setup_logging(self): + logging.basicConfig(level=self.log_level) + self.root_logger.setLevel(self.log_level) + self.log.setLevel(self.verbosity) + def _cleanup_tempdir(self) -> None: if "tempdir" in self.__dict__: self.tempdir.cleanup() @@ -160,6 +211,9 @@ def _cleanup_tempdir(self) -> None: class Runner(BaseRunner): + def __call__(self) -> Optional[int]: + return self.run() + @cleansup def run(self) -> Optional[int]: raise NotImplementedError diff --git a/envoy.base.runner/tests/test_abstract.py b/envoy.base.runner/tests/test_abstract.py index 9f2ace424..c920b18b0 100644 --- a/envoy.base.runner/tests/test_abstract.py +++ b/envoy.base.runner/tests/test_abstract.py @@ -12,6 +12,9 @@ @abstracts.implementer(AAsyncRunnerWithCommands) class DummyAsyncRunnerWithCommands: + def __init__(self): + pass + @property def command(self): return super().command diff --git a/envoy.base.runner/tests/test_runner.py b/envoy.base.runner/tests/test_runner.py index cf85b7ef5..1f0642127 100644 --- a/envoy.base.runner/tests/test_runner.py +++ b/envoy.base.runner/tests/test_runner.py @@ -1,3 +1,5 @@ + +import logging import sys from unittest.mock import AsyncMock, MagicMock, patch, PropertyMock @@ -61,6 +63,40 @@ async def run_async(self, *args, **kwargs): return DummyFailingRunner +def test_base_log_filter(): + filter = runner.runner.BaseLogFilter("APP_LOGGER") + assert isinstance(filter, logging.Filter) + assert filter.app_logger == "APP_LOGGER" + + +@pytest.mark.parametrize("name", ["APP_LOGGER", "SOMETHING_ELSE"]) +def test_app_log_filter(name): + app_logger = MagicMock() + app_logger.name = "APP_LOGGER" + filter = runner.runner.AppLogFilter(app_logger) + assert isinstance(filter, runner.runner.BaseLogFilter) + assert filter.app_logger == app_logger + record = MagicMock() + record.name = name + assert ( + filter.filter(record) + == (name == "APP_LOGGER")) + + +@pytest.mark.parametrize("name", ["APP_LOGGER", "SOMETHING_ELSE"]) +def test_root_log_filter(name): + app_logger = MagicMock() + app_logger.name = "APP_LOGGER" + filter = runner.runner.RootLogFilter(app_logger) + assert isinstance(filter, runner.runner.BaseLogFilter) + assert filter.app_logger == app_logger + record = MagicMock() + record.name = name + assert ( + filter.filter(record) + == (name != "APP_LOGGER")) + + @pytest.mark.asyncio @pytest.mark.parametrize("async_fun", [True, False]) @pytest.mark.parametrize( @@ -188,21 +224,32 @@ async def test_cleansup(async_fun, raises): == [(), {}]) -def test_base_runner_constructor(): - run = runner.BaseRunner("path1", "path2", "path3") +def test_base_runner_constructor(patches): + patched = patches( + "BaseRunner.setup_logging", + prefix="envoy.base.runner.runner") + + with patched as (m_setup, ): + run = runner.BaseRunner("path1", "path2", "path3") + + assert ( + m_setup.call_args + == [(), {}]) assert run._args == ("path1", "path2", "path3") assert run.log_field_styles == runner.runner.LOG_FIELD_STYLES assert run.log_level_styles == runner.runner.LOG_LEVEL_STYLES assert run.log_fmt == runner.runner.LOG_FMT -def test_base_runner_args(): - run = runner.BaseRunner("path1", "path2", "path3") - parser_mock = patch( - "envoy.base.runner.runner.BaseRunner.parser", - new_callable=PropertyMock) +def test_base_runner_args(patches): + patched = patches( + ("BaseRunner.parser", + dict(new_callable=PropertyMock)), + "BaseRunner.setup_logging", + prefix="envoy.base.runner.runner") - with parser_mock as m_parser: + with patched as (m_parser, m_setup): + run = runner.BaseRunner('path1', 'path2', 'path3') known_args = m_parser.return_value.parse_known_args assert ( run.args @@ -217,13 +264,15 @@ def test_base_runner_args(): assert "args" in run.__dict__ -def test_base_runner_extra_args(): - run = runner.BaseRunner("path1", "path2", "path3") - parser_mock = patch( - "envoy.base.runner.runner.BaseRunner.parser", - new_callable=PropertyMock) +def test_base_runner_extra_args(patches): + patched = patches( + ("BaseRunner.parser", + dict(new_callable=PropertyMock)), + "BaseRunner.setup_logging", + prefix="envoy.base.runner.runner") - with parser_mock as m_parser: + with patched as (m_parser, m_setup): + run = runner.BaseRunner('path1', 'path2', 'path3') known_args = m_parser.return_value.parse_known_args assert ( run.extra_args @@ -239,46 +288,46 @@ def test_base_runner_extra_args(): def test_base_runner_log(patches): - run = runner.BaseRunner("path1", "path2", "path3") patched = patches( - "logging.getLogger", "coloredlogs", "verboselogs", - ("BaseRunner.log_level", dict(new_callable=PropertyMock)), - ("BaseRunner.log_level_styles", dict(new_callable=PropertyMock)), - ("BaseRunner.log_field_styles", dict(new_callable=PropertyMock)), - ("BaseRunner.log_fmt", dict(new_callable=PropertyMock)), - ("BaseRunner.name", dict(new_callable=PropertyMock)), + ("BaseRunner.log_field_styles", + dict(new_callable=PropertyMock)), + ("BaseRunner.log_fmt", + dict(new_callable=PropertyMock)), + ("BaseRunner.log_level_styles", + dict(new_callable=PropertyMock)), + ("BaseRunner.name", + dict(new_callable=PropertyMock)), + ("BaseRunner.verbosity", + dict(new_callable=PropertyMock)), + "BaseRunner.setup_logging", prefix="envoy.base.runner.runner") with patched as patchy: - (m_logger, m_color, m_verb, - m_level, m_lstyle, m_fstyle, m_fmt, m_name) = patchy - assert run.log == m_logger.return_value + (m_color, m_verb, m_fstyle, m_fmt, + m_lstyle, m_name, m_verbosity, m_setup) = patchy + run = runner.BaseRunner('path1', 'path2', 'path3') + assert run.log == m_verb.VerboseLogger.return_value assert ( - list(m_verb.install.call_args) - == [(), {}]) - assert ( - list(m_logger.return_value.setLevel.call_args) - == [(m_level.return_value,), {}]) - assert ( - list(m_logger.return_value.setLevel.call_args) - == [(m_level.return_value,), {}]) + m_verb.VerboseLogger.call_args + == [(m_name.return_value, ), {}]) + assert ( - list(m_color.install.call_args) + m_color.install.call_args == [(), {'fmt': m_fmt.return_value, 'isatty': True, 'field_styles': m_fstyle.return_value, - 'level': 'DEBUG', + 'level': m_verbosity.return_value, 'level_styles': m_lstyle.return_value, - 'logger': m_logger.return_value}]) + 'logger': m_verb.VerboseLogger.return_value}]) assert "log" in run.__dict__ def test_base_runner_log_level(patches): - run = runner.BaseRunner("path1", "path2", "path3") + run = DummyRunner() patched = patches( "dict", ("BaseRunner.args", dict(new_callable=PropertyMock)), @@ -302,25 +351,25 @@ def test_base_runner_name(): def test_base_runner_parser(patches): - run = runner.BaseRunner("path1", "path2", "path3") + run = DummyRunner() patched = patches( - "argparse.ArgumentParser", + "argparse", "BaseRunner.add_arguments", prefix="envoy.base.runner.runner") with patched as (m_parser, m_add_args): - assert run.parser == m_parser.return_value + assert run.parser == m_parser.ArgumentParser.return_value assert ( - list(m_parser.call_args) + list(m_parser.ArgumentParser.call_args) == [(), {"allow_abbrev": False}]) assert ( list(m_add_args.call_args) - == [(m_parser.return_value,), {}]) + == [(m_parser.ArgumentParser.return_value,), {}]) assert "parser" in run.__dict__ def test_base_runner_path(patches): - run = runner.BaseRunner("path1", "path2", "path3") + run = DummyRunner() patched = patches( "pathlib", prefix="envoy.base.runner.runner") @@ -333,9 +382,86 @@ def test_base_runner_path(patches): == [(".", ), {}]) -def test_base_runner_stdout(patches): - run = runner.BaseRunner("path1", "path2", "path3") +def test_base_runner_root_log_format(patches): + run = DummyRunner() + patched = patches( + "logging", + prefix="envoy.base.runner.runner") + with patched as (m_logging, ): + assert run.root_log_format == m_logging.Formatter.return_value + + assert ( + m_logging.Formatter.call_args + == [("%(name)s: %(levelname)s %(message)s", ), {}]) + assert "root_log_format" not in run.__dict__ + + +def test_base_runner_root_log_handler(patches): + run = DummyRunner() + patched = patches( + "logging", + "RootLogFilter", + ("BaseRunner.log", dict(new_callable=PropertyMock)), + ("BaseRunner.log_level", dict(new_callable=PropertyMock)), + ("BaseRunner.root_log_format", dict(new_callable=PropertyMock)), + prefix="envoy.base.runner.runner") + + with patched as (m_logging, m_filter, m_log, m_level, m_format): + assert run.root_log_handler == m_logging.StreamHandler.return_value + + assert ( + m_logging.StreamHandler.call_args + == [(), {}]) + assert ( + m_logging.StreamHandler.return_value.setLevel.call_args + == [(m_level.return_value, ), {}]) + assert ( + m_logging.StreamHandler.return_value.addFilter.call_args + == [(m_filter.return_value, ), {}]) + assert ( + m_filter.call_args + == [(m_log.return_value, ), {}]) + assert ( + m_logging.StreamHandler.return_value.setFormatter.call_args + == [(m_format.return_value, ), {}]) + assert "root_log_handler" in run.__dict__ + + +def test_base_runner_root_logger(patches): + run = DummyRunner() + patched = patches( + "logging", + "AppLogFilter", + ("BaseRunner.log", dict(new_callable=PropertyMock)), + ("BaseRunner.root_log_handler", dict(new_callable=PropertyMock)), + prefix="envoy.base.runner.runner") + + with patched as (m_logging, m_filter, m_log, m_handler): + assert run.root_logger == m_logging.getLogger.return_value + + assert ( + m_logging.getLogger.call_args + == [(), {}]) + assert ( + m_logging.getLogger.return_value.handlers.__getitem__.call_args + == [(0, ), {}]) + assert ( + m_logging.getLogger.return_value + .handlers.__getitem__.return_value + .addFilter.call_args + == [(m_filter.return_value, ), {}]) + assert ( + m_filter.call_args + == [(m_log.return_value, ), {}]) + assert ( + m_logging.getLogger.return_value.addHandler.call_args + == [(m_handler.return_value, ), {}]) + assert "root_logger" in run.__dict__ + + +def test_base_runner_stdout(patches): + run = DummyRunner() patched = patches( "logging", ("BaseRunner.log_level", dict(new_callable=PropertyMock)), @@ -366,7 +492,7 @@ def test_base_runner_stdout(patches): @pytest.mark.parametrize("missing", [True, False]) def test_base_runner_tempdir(patches, missing): - run = runner.BaseRunner() + run = DummyRunner() patched = patches( "tempfile", ("BaseRunner.log", dict(new_callable=PropertyMock)), @@ -391,18 +517,72 @@ def test_base_runner_tempdir(patches, missing): assert "tempdir" in run.__dict__ +def test_base_runner_verbosity(patches): + run = DummyRunner() + patched = patches( + "dict", + ("BaseRunner.args", dict(new_callable=PropertyMock)), + prefix="envoy.base.runner.runner") + with patched as (m_dict, m_args): + assert run.verbosity == m_dict.return_value.__getitem__.return_value + + assert ( + list(m_dict.call_args) + == [(runner.runner.LOG_LEVELS, ), {}]) + assert ( + list(m_dict.return_value.__getitem__.call_args) + == [(m_args.return_value.verbosity,), {}]) + assert "verbosity" in run.__dict__ + + def test_base_runner_add_arguments(): - run = runner.BaseRunner("path1", "path2", "path3") + run = DummyRunner() parser = MagicMock() assert run.add_arguments(parser) is None assert ( list(list(c) for c in parser.add_argument.call_args_list) - == [[('--log-level', '-l'), + == [[('--verbosity', + '-v'), + {'choices': ['debug', + 'info', + 'warn', + 'error'], + 'default': 'info', + 'help': 'Application log level'}], + [('--log-level', '-l'), {'choices': ['debug', 'info', 'warn', 'error'], - 'default': 'info', 'help': 'Log level to display'}], - ]) + 'default': 'warn', + 'help': 'Log level for non-application logs'}]]) + + +def test_runner_setup_logging(patches): + run = DummyRunner() + patched = patches( + "logging", + ("BaseRunner.log", + dict(new_callable=PropertyMock)), + ("BaseRunner.log_level", + dict(new_callable=PropertyMock)), + ("BaseRunner.root_logger", + dict(new_callable=PropertyMock)), + ("BaseRunner.verbosity", + dict(new_callable=PropertyMock)), + prefix="envoy.base.runner.runner") + + with patched as (m_logging, m_log, m_level, m_root, m_verb): + assert not run.setup_logging() + + assert ( + m_logging.basicConfig.call_args + == [(), dict(level=m_level.return_value)]) + assert ( + m_root.return_value.setLevel.call_args + == [(m_level.return_value, ), {}]) + assert ( + m_log.return_value.setLevel.call_args + == [(m_verb.return_value, ), {}]) @pytest.mark.parametrize("has_fun", [True, False]) @@ -412,7 +592,7 @@ def test_base_runner__missing_cleanup(has_fun, is_wrapped, cleansup): def _runner_factory(): if not has_fun: - return runner.BaseRunner() + return DummyRunner() class _Wrap: if cleansup: @@ -422,10 +602,10 @@ class _Wrapper: if is_wrapped: __wrapped__ = _Wrap() - class DummyRunner(runner.BaseRunner): + class DummyRunner2(DummyRunner): run = _Wrapper() - return DummyRunner() + return DummyRunner2() run = _runner_factory() @@ -438,7 +618,7 @@ class DummyRunner(runner.BaseRunner): @pytest.mark.parametrize("cached", [True, False]) def test_base_runner__cleanup_tempdir(patches, cached): - run = runner.BaseRunner() + run = DummyRunner() patched = patches( ("BaseRunner.tempdir", dict(new_callable=PropertyMock)), prefix="envoy.base.runner.runner") @@ -475,12 +655,13 @@ def test_runner_constructor(patches): def test_runner_dunder_call(patches): - run = runner.Runner() patched = patches( "Runner.run", + "Runner.setup_logging", prefix="envoy.base.runner.runner") - with patched as (m_run, ): + with patched as (m_run, m_setup): + run = runner.Runner() assert run() == m_run.return_value assert ( @@ -489,12 +670,13 @@ def test_runner_dunder_call(patches): def test_runner_cleanup(patches): - run = runner.Runner() patched = patches( "Runner._cleanup_tempdir", + "Runner.setup_logging", prefix="envoy.base.runner.runner") - with patched as (m_temp, ): + with patched as (m_temp, m_setup): + run = runner.Runner() assert not run.cleanup() assert ( @@ -521,13 +703,17 @@ def test_async_runner_constructor(patches): @pytest.mark.parametrize("raises", [None, KeyboardInterrupt]) def test_async_runner_dunder_call(patches, raises): - run = runner.AsyncRunner() patched = patches( "asyncio", + ("AsyncRunner.log", dict(new_callable=MagicMock)), ("AsyncRunner.run", dict(new_callable=MagicMock)), + "AsyncRunner.setup_logging", prefix="envoy.base.runner.runner") - with patched as (m_asyncio, m_run): + # TODO: TEST LOG + + with patched as (m_asyncio, m_log, m_run, m_setup): + run = runner.AsyncRunner() if raises: m_run.side_effect = raises("DIE") assert ( @@ -549,12 +735,13 @@ def test_async_runner_dunder_call(patches, raises): @pytest.mark.asyncio async def test_async_runner_cleanup(patches): - run = runner.AsyncRunner() patched = patches( "AsyncRunner._cleanup_tempdir", + "AsyncRunner.setup_logging", prefix="envoy.base.runner.runner") - with patched as (m_temp, ): + with patched as (m_temp, m_setup): + run = runner.AsyncRunner() assert not await run.cleanup() assert ( @@ -718,12 +905,16 @@ def test_forkingadapter_subproc_run(patches, args, cwd, capture_output): # ForkingRunner tests -def test_forkingrunner_fork(): - run = runner.ForkingRunner("path1", "path2", "path3") - forking_mock = patch("envoy.base.runner.runner.ForkingAdapter") +def test_forkingrunner_fork(patches): + patched = patches( + "ForkingAdapter", + "ForkingRunner.setup_logging", + prefix="envoy.base.runner.runner") - with forking_mock as m_fork: + with patched as (m_fork, m_setup): + run = runner.ForkingRunner("path1", "path2", "path3") assert run.subproc_run == m_fork.return_value + assert ( list(m_fork.call_args) == [(run,), {}]) @@ -732,11 +923,14 @@ def test_forkingrunner_fork(): # BazelRunner tests -def test_bazelrunner_bazel(): - run = runner.BazelRunner("path1", "path2", "path3") - bazel_mock = patch("envoy.base.runner.runner.BazelAdapter") +def test_bazelrunner_bazel(patches): + patched = patches( + "BazelAdapter", + "BazelRunner.setup_logging", + prefix="envoy.base.runner.runner") - with bazel_mock as m_bazel: + with patched as (m_bazel, m_setup): + run = runner.BazelRunner("path1", "path2", "path3") assert run.bazel == m_bazel.return_value assert ( list(m_bazel.call_args)