feature/mx-1626 move log timestamp into formatter (#225)

# PR Context
- this works better with dagster log capturing
- also needs less code

# Changes
- move log timestamp and coloring into the formatter

---------

Co-authored-by: Kamran Ali <[email protected]>

CHANGELOG.md

@@ -11,8 +11,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Changes
 
+- move log timestamp and coloring into the formatter
+
 ### Deprecated
 
+- `mex.common.logging.echo` is deprecated in favor of `logging.info`
+
 ### Removed
 
 ### Fixed

mex/common/cli.py

@@ -15,7 +15,7 @@
 from pydantic.fields import FieldInfo
 
 from mex.common.connector import CONNECTOR_STORE
-from mex.common.logging import echo, logger
+from mex.common.logging import logger
 from mex.common.settings import SETTINGS_STORE, BaseSettings
 from mex.common.transform import MExEncoder
 
@@ -145,11 +145,11 @@ def _callback(
             pdb.post_mortem(sys.exc_info()[2])
             raise error
         # if not in debug mode, exit with code 1.
-        echo("exit", fg="red")
+        logger.error("exit")
         context.exit(1)
 
     # all good, exit with code 0.
-    echo("done", fg="green")
+    logger.info("done")
     context.exit(0)
 
 

mex/common/extract.py

@@ -7,7 +7,7 @@
 import pandas as pd
 from pydantic import ValidationError
 
-from mex.common.logging import echo
+from mex.common.logging import logger
 
 if TYPE_CHECKING:  # pragma: no cover
     from pandas._typing import Dtype, ReadCsvBuffer
@@ -63,12 +63,17 @@ def parse_csv(
                 row.replace(regex=r"^\s*$", value=None, inplace=True)
                 try:
                     model = into.model_validate(row.to_dict())
-                    echo(f"[parse csv] {into.__name__} {index} OK")
+                    logger.info(
+                        "parse_csv - %s %s - OK",
+                        into.__name__,
+                        index,
+                    )
                     yield model
                 except ValidationError as error:
-                    echo(
-                        f"[parse csv] {into.__name__} {index} "
-                        f"{error.__class__.__name__} "
-                        f"Errors: {error.errors()}",
-                        fg="red",
+                    logger.error(
+                        "parse_csv - %s %s - %s - %s",
+                        into.__name__,
+                        index,
+                        error.__class__.__name__,
+                        error.errors(),
                     )

mex/common/logging.py

@@ -1,7 +1,6 @@
 import logging
 import logging.config
 from collections.abc import Callable, Generator
-from datetime import datetime
 from functools import wraps
 from typing import Any, TypeVar
 
@@ -14,7 +13,8 @@
     "disable_existing_loggers": False,
     "formatters": {
         "default": {
-            "format": "%(message)s",
+            "format": f"{click.style('%(asctime)s', fg='bright_yellow')}"
+            " - mex - %(message)s",
         }
     },
     "handlers": {
@@ -35,6 +35,7 @@
 }
 logging.config.dictConfig(LOGGING_CONFIG)
 logger = logging.getLogger("mex")
+echo = logger.info  # `echo` is deprecated, use the logger directly instead
 
 
 def watch(
@@ -52,25 +53,8 @@ def watch(
 
     @wraps(func)
     def wrapper(*args: Any, **kwargs: Any) -> Generator[_YieldT, None, None]:
-        fname = func.__name__.replace("_", " ")
         for item in func(*args, **kwargs):
-            echo(f"[{fname}] {item}")
+            logger.info("%s - %s", func.__name__, item)
             yield item
 
     return wrapper
-
-
-def get_ts(ts: datetime | None = None) -> str:
-    """Get a styled timestamp tag for prefixing log messages."""
-    return click.style(f"[{ts or datetime.now()}]", fg="bright_yellow")
-
-
-def echo(text: str | bytes, ts: datetime | None = None, **styles: Any) -> None:
-    """Echo the given text with the given styles and the current timestamp prefix.
-
-    Args:
-        text: Text to print to the console
-        ts: Timestamp to print as prefix, defaults to `now()`
-        styles: Keyword parameters to be passed to `click.style`
-    """
-    logger.info(f"{get_ts(ts)} {click.style(text, **styles)}")

mex/common/sinks/ndjson.py

@@ -4,7 +4,7 @@
 from pathlib import Path
 from typing import IO, Any
 
-from mex.common.logging import echo, watch
+from mex.common.logging import logger, watch
 from mex.common.models import AnyExtractedModel
 from mex.common.settings import BaseSettings
 from mex.common.transform import MExEncoder
@@ -37,9 +37,10 @@ def write_ndjson(
                 file_name = Path(settings.work_dir, f"{class_name}.ndjson")
                 writer = open(file_name, "a+", encoding="utf-8")
                 file_handles[class_name] = handle = stack.enter_context(writer)
-                echo(
-                    f"[writing {class_name} to file] {file_name.as_posix()}",
-                    fg="green",
+                logger.info(
+                    "write_ndjson - writing %s to file %s",
+                    class_name,
+                    file_name.as_posix(),
                 )
 
             json.dump(model, handle, sort_keys=True, cls=MExEncoder)

tests/test_extract.py

@@ -45,5 +45,5 @@ def test_parse_csv(caplog: LogCaptureFixture) -> None:
     }
     assert len(caplog.text.splitlines()) == 2
     good_row_log, bad_row_log = caplog.text.splitlines()
-    assert "[parse csv] DummyModel 0 OK" in good_row_log
-    assert "[parse csv] DummyModel 1 ValidationError" in bad_row_log
+    assert "parse_csv - DummyModel 0 - OK" in good_row_log
+    assert "parse_csv - DummyModel 1 - ValidationError" in bad_row_log

tests/test_logging.py

@@ -1,12 +1,11 @@
 import logging
-from datetime import datetime
 from typing import Any
 from uuid import UUID
 
 from pytest import LogCaptureFixture
 
 from mex.common.exceptions import MExError
-from mex.common.logging import echo, get_ts, watch
+from mex.common.logging import watch
 
 
 def test_watch(caplog: LogCaptureFixture) -> None:
@@ -26,20 +25,6 @@ def dummy_generator() -> Any:
     # check captured logging
     assert len(caplog.messages) == 3
     str_line, uuid_line, error_line = caplog.messages
-    assert "[dummy generator] foo" in str_line
-    assert "[dummy generator] 00000000-0000-4000-8000-000000000010" in uuid_line
-    assert "[dummy generator] MExError: foo, 42" in error_line
-
-
-def test_get_ts() -> None:
-    assert get_ts(datetime(1999, 12, 31, 23, 59, 59)) == (
-        "\x1b[93m[1999-12-31 23:59:59]\x1b[0m"
-    )
-
-
-def test_echo(caplog: LogCaptureFixture) -> None:
-    # echo while capturing logs
-    with caplog.at_level(logging.INFO, logger="mex"):
-        echo("This is going well", ts=datetime(1999, 12, 31, 23, 59, 59))
-
-    assert "[1999-12-31 23:59:59] This is going well" in caplog.text
+    assert "dummy_generator - foo" in str_line
+    assert "dummy_generator - 00000000-0000-4000-8000-000000000010" in uuid_line
+    assert "dummy_generator - MExError: foo, 42" in error_line