diff --git a/goth/assertions/monitor.py b/goth/assertions/monitor.py index c526ae4a..11c2c995 100644 --- a/goth/assertions/monitor.py +++ b/goth/assertions/monitor.py @@ -10,6 +10,8 @@ import sys from typing import Callable, Generic, List, Optional, Sequence, Union +import colors + from goth.assertions import Assertion, AssertionFunction, E @@ -257,15 +259,20 @@ async def _check_assertions(self, events_ended: bool) -> None: await a.update_events(events_ended=events_ended) + if a.done: + self._logger.debug( + "Assertion '%s' finished after event %s", a.name, event_descr + ) + if a.accepted: result = a.result() - msg = "Assertion '%s' succeeded after event: %s; result: %s" - self._logger.log(level, msg, a.name, event_descr, result) + msg = colors.green("Assertion '%s' succeeded; result: %s", style="bold") + self._logger.log(level, msg, a.name, result) elif a.failed: - await self._report_failure(a, event_descr) + await self._report_failure(a) - async def _report_failure(self, a: Assertion, event_descr: str) -> None: + async def _report_failure(self, a: Assertion) -> None: try: a.result() except Exception as exc: @@ -276,10 +283,8 @@ async def _report_failure(self, a: Assertion, event_descr: str) -> None: # functions are left. for _ in (1, 2, 3): tb = tb.tb_next if tb else tb - msg = "Assertion '%s' failed after event: %s; cause: %s" - self._logger.error( - msg, a.name, event_descr, exc, exc_info=(type(exc), exc, tb) - ) + msg = colors.red("Assertion '%s' failed; cause: %s", style="bold") + self._logger.error(msg, a.name, exc, exc_info=(type(exc), exc, tb)) @property def satisfied(self) -> Sequence[Assertion[E]]: diff --git a/goth/runner/log.py b/goth/runner/log.py index 0a1f2dc2..2613e35f 100644 --- a/goth/runner/log.py +++ b/goth/runner/log.py @@ -9,6 +9,8 @@ import time from typing import Iterator, Optional, Union +import colors + import goth import goth.api_monitor from goth.assertions.monitor import EventMonitor @@ -20,19 +22,24 @@ logger = logging.getLogger(__name__) -class UTCFormatter(logging.Formatter): - """Custom `logging` formatter that uses `time.gmtime`.""" +class CustomFileLogFormatter(logging.Formatter): + """`Formatter` that uses `time.gmtime` for time and strips ANSI color codes.""" converter = time.gmtime + def format(self, record: logging.LogRecord) -> str: + """Format the message and remove ANSI color codes from it.""" + text = super().format(record) + return colors.strip_color(text) + LOGGING_CONFIG = { "version": 1, "formatters": { "none": {"format": "%(message)s"}, - "simple": {"format": "%(levelname)-8s [%(name)-30s] %(message)s"}, - "date": { - "()": UTCFormatter, + "console": {"format": "%(levelname)-8s [%(name)-30s] %(message)s"}, + "file": { + "()": CustomFileLogFormatter, "format": "%(asctime)s %(levelname)-8s %(name)-30s %(message)s", "datefmt": "%Y-%m-%d %H:%M:%S%z", }, @@ -40,12 +47,12 @@ class UTCFormatter(logging.Formatter): "handlers": { "console": { "class": "logging.StreamHandler", - "formatter": "simple", + "formatter": "console", "level": "INFO", }, "runner_file": { "class": "logging.FileHandler", - "formatter": "date", + "formatter": "file", "filename": "%(base_log_dir)s/runner.log", "encoding": "utf-8", "level": "DEBUG", @@ -123,9 +130,9 @@ def configure_logging_for_test(test_log_dir: Path) -> None: proxy_handler = None try: - formatter = logging.Formatter( - fmt=LOGGING_CONFIG["formatters"]["date"]["format"], - datefmt=LOGGING_CONFIG["formatters"]["date"]["datefmt"], + formatter = CustomFileLogFormatter( + fmt=LOGGING_CONFIG["formatters"]["file"]["format"], + datefmt=LOGGING_CONFIG["formatters"]["file"]["datefmt"], ) # TODO: ensure the new files created here do not conflict with probe logs @@ -148,16 +155,25 @@ def configure_logging_for_test(test_log_dir: Path) -> None: api_monitor_logger.handlers.remove(proxy_handler) -class MonitorHandler(logging.Handler): - """A logging handler that passes messages from log records to an event monitor.""" +class MonitoringFilter(logging.Filter): + """A logging `Filter` that feeds messages to the underlying event monitor. + + After doing this it also adds some color to the messages for greater fun. + """ - def __init__(self, monitor: EventMonitor[str]): - self._monitor = monitor + def __init__(self, monitor: EventMonitor[str], color: Optional[str] = None): super().__init__() + self._monitor: EventMonitor[str] = monitor + self._color: Optional[str] = color - def handle(self, record: logging.LogRecord) -> None: - """Add the `record`'s message to the associated event monitor.""" - self._monitor.add_event_sync(record.getMessage()) + def filter(self, record: logging.LogRecord) -> bool: + """Pass the record's message to the monitor, add colors to the message.""" + message = record.getMessage() + self._monitor.add_event_sync(message) + if self._color: + record.msg = colors.color(message, fg=self._color) + record.args = () + return True @contextlib.contextmanager @@ -170,10 +186,9 @@ def monitored_logger(name: str, monitor: EventMonitor[str]) -> Iterator[logging. """ logger_ = logging.getLogger(name) - handler = MonitorHandler(monitor) + filter = MonitoringFilter(monitor, "cyan") + logger_.filters.insert(0, filter) try: - logger_.addHandler(handler) yield logger_ finally: - if handler in logger_.handlers: - logger_.removeHandler(handler) + logger.removeFilter(filter) diff --git a/poetry.lock b/poetry.lock index d9dd0368..6a1249fa 100644 --- a/poetry.lock +++ b/poetry.lock @@ -17,6 +17,14 @@ yarl = ">=1.0,<2.0" [package.extras] speedups = ["aiodns", "brotlipy", "cchardet"] +[[package]] +name = "ansicolors" +version = "1.1.8" +description = "ANSI colors for Python" +category = "main" +optional = false +python-versions = "*" + [[package]] name = "appdirs" version = "1.4.4" @@ -1059,7 +1067,7 @@ python-versions = "*" [metadata] lock-version = "1.1" python-versions = "^3.8" -content-hash = "41590214a81b4fd9c43ba4f771d3e1c6048303ac35ba081bff46dcdcd5be789c" +content-hash = "be1ddabb234a8c4e849a5fa554ab54da0979496594ae4ad6ac1fc35dc7cf4609" [metadata.files] aiohttp = [ @@ -1101,6 +1109,10 @@ aiohttp = [ {file = "aiohttp-3.7.3-cp39-cp39-win_amd64.whl", hash = "sha256:e1b95972a0ae3f248a899cdbac92ba2e01d731225f566569311043ce2226f5e7"}, {file = "aiohttp-3.7.3.tar.gz", hash = "sha256:9c1a81af067e72261c9cbe33ea792893e83bc6aa987bfbd6fdc1e5e7b22777c4"}, ] +ansicolors = [ + {file = "ansicolors-1.1.8-py2.py3-none-any.whl", hash = "sha256:00d2dde5a675579325902536738dd27e4fac1fd68f773fe36c21044eb559e187"}, + {file = "ansicolors-1.1.8.zip", hash = "sha256:99f94f5e3348a0bcd43c82e5fc4414013ccc19d70bd939ad71e0133ce9c372e0"}, +] appdirs = [ {file = "appdirs-1.4.4-py2.py3-none-any.whl", hash = "sha256:a841dacd6b99318a741b166adb07e19ee71a274450e68237b4650ca1055ab128"}, {file = "appdirs-1.4.4.tar.gz", hash = "sha256:7d5d0167b2b1ba821647616af46a749d1c653740dd0d2415100fe26e27afdf41"}, @@ -1166,6 +1178,8 @@ brotli = [ {file = "Brotli-1.0.9-cp39-cp39-macosx_10_9_x86_64.whl", hash = "sha256:5cb1e18167792d7d21e21365d7650b72d5081ed476123ff7b8cac7f45189c0c7"}, {file = "Brotli-1.0.9-cp39-cp39-manylinux1_i686.whl", hash = "sha256:16d528a45c2e1909c2798f27f7bf0a3feec1dc9e50948e738b961618e38b6a7b"}, {file = "Brotli-1.0.9-cp39-cp39-manylinux1_x86_64.whl", hash = "sha256:56d027eace784738457437df7331965473f2c0da2c70e1a1f6fdbae5402e0389"}, + {file = "Brotli-1.0.9-cp39-cp39-win32.whl", hash = "sha256:cfc391f4429ee0a9370aa93d812a52e1fee0f37a81861f4fdd1f4fb28e8547c3"}, + {file = "Brotli-1.0.9-cp39-cp39-win_amd64.whl", hash = "sha256:854c33dad5ba0fbd6ab69185fec8dab89e13cda6b7d191ba111987df74f38761"}, {file = "Brotli-1.0.9.zip", hash = "sha256:4d1b810aa0ed773f81dceda2cc7b403d01057458730e309856356d4ef4188438"}, ] certifi = [ diff --git a/pyproject.toml b/pyproject.toml index 7f890754..3755685d 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -24,6 +24,7 @@ readme = "README.md" [tool.poetry.dependencies] python = "^3.8" aiohttp = "3.7.3" +ansicolors = "^1.1.0" docker-compose = "^1.29" docker = "^5.0" func_timeout = "4.3.5"