Add some 🟥🟧🟨🟩🟦🟪 to the logs

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]]:

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,32 +22,37 @@
 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",
         },
     },
     "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)

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"