Repository: theacodes/nox
Pull request #323 (2020-05-09 21:29:44)

draft: --add-timestamp
introducing an --add_timestamp flag and support for in in the logging system.

#289 

omry: 1. Looking for overall feedback.
2. colorlog test is failing even though things are working. looks like some kind of interaction between colorlog and logcap.

omry: Screen shots:

![image](https://user-images.githubusercontent.com/376455/81485417-be16a880-9201-11ea-9d69-6985d69226d9.png)
![image](https://user-images.githubusercontent.com/376455/81485426-cbcc2e00-9201-11ea-98e8-2912d0d8e5f9.png)

omry: @theacodes ping
theacodes: > Looking for overall feedback (Is it okay to add the flag? is the log format okay? [I noticed it's missing nox> )

This is a great idea. I would definitely add the `nox >`, as it's important to be able to distinguish Nox's output from the output that programs called via `run` produce.

> colorlog test is failing even though things are working. looks like some kind of interaction between colorlog and logcap.

We'll definitely wanna get that working, but I'm not a fan of using subprocess in tests unless its absolutely necessary.


omry: > We'll definitely wanna get that working, but I'm not a fan of using subprocess in tests unless its absolutely necessary.

The problem I ran into was that for an unknown reason, asctime was not populated in the caplog record when using colorlog. but we are talking about an interaction between two third party libs (caplog and colorlib), through the somewhat complicated Python logging subsystem.

I already spent about an hour or two digging into it. I will give it another shot before resorting to process testing.
omry: responded to comments, except the test.
Upon further digging, I suspect custom log formatter are [not fully supported](https://github.com/pytest-dev/pytest/issues/2987) by pytest caplog.

I see two options:
1. Drop the testing timestamp override testing for the colorlog. This is very visible so if it breaks we will hear about it and keep the current working testing for non-colorlog mode.
2. Switch both test modes to process based testing.

What do you think?
theacodes: Sorry for taking so long to get to this. Let's go with (1).
omry: ### Regular run
![image](https://user-images.githubusercontent.com/376455/84986601-ad582d00-b0f3-11ea-8bd9-9b27a1b83606.png)

### Run with timestamps
![image](https://user-images.githubusercontent.com/376455/84986681-cd87ec00-b0f3-11ea-9328-3e609f6912b3.png)

### Runt with timestamp and no color.
![image](https://user-images.githubusercontent.com/376455/84986737-e7293380-b0f3-11ea-9968-90d1852467ec.png)

omry: I noticed that there is some cleanup to do:
1. blacken is not running and seems to be producing results different than `black .`. it should probably be removed from the noxfile.
2. docs/conf.py needs black formatting.


Patch:
diff --git a/nox/__main__.py b/nox/__main__.py
index f81412c..2f551cc 100644
--- a/nox/__main__.py
+++ b/nox/__main__.py
@@ -41,7 +41,9 @@ def main() -> None:
         print(metadata.version("nox"), file=sys.stderr)
         return
 
-    setup_logging(color=args.color, verbose=args.verbose)
+    setup_logging(
+        color=args.color, verbose=args.verbose, add_timestamp=args.add_timestamp
+    )
 
     # Execute the appropriate tasks.
     exit_code = workflow.execute(
diff --git a/nox/_options.py b/nox/_options.py
index a46943a..336cff5 100644
--- a/nox/_options.py
+++ b/nox/_options.py
@@ -264,6 +264,15 @@ options.add_options(
         help="Logs the output of all commands run including commands marked silent.",
         noxfile=True,
     ),
+    _option_set.Option(
+        "add_timestamp",
+        "-ts",
+        "--add-timestamp",
+        group=options.groups["secondary"],
+        action="store_true",
+        help="Adds a timestamp to logged output.",
+        noxfile=True,
+    ),
     _option_set.Option(
         "default_venv_backend",
         "-db",
diff --git a/nox/logger.py b/nox/logger.py
index 9d24105..84d5fcc 100644
--- a/nox/logger.py
+++ b/nox/logger.py
@@ -21,15 +21,53 @@ SUCCESS = 25
 OUTPUT = logging.DEBUG - 1
 
 
-class NoxFormatter(ColoredFormatter):
-    def __init__(self, *args: Any, **kwargs: Any) -> None:
-        super(NoxFormatter, self).__init__(*args, **kwargs)
+def _get_format(colorlog: bool, add_timestamp: bool) -> str:
+    if colorlog:
+        if add_timestamp:
+            return "%(cyan)s%(name)s > [%(asctime)s] %(log_color)s%(message)s"
+        else:
+            return "%(cyan)s%(name)s > %(log_color)s%(message)s"
+    else:
+        if add_timestamp:
+            return "%(name)s > [%(asctime)s] %(message)s"
+        else:
+            return "%(name)s > %(message)s"
+
+
+class NoxFormatter(logging.Formatter):
+    def __init__(self, add_timestamp: bool = False) -> None:
+        super().__init__(fmt=_get_format(colorlog=False, add_timestamp=add_timestamp))
         self._simple_fmt = logging.Formatter("%(message)s")
 
     def format(self, record: Any) -> str:
         if record.levelname == "OUTPUT":
             return self._simple_fmt.format(record)
-        return super(NoxFormatter, self).format(record)
+        return super().format(record)
+
+
+class NoxColoredFormatter(ColoredFormatter):
+    def __init__(
+        self,
+        datefmt: Any = None,
+        style: Any = None,
+        log_colors: Any = None,
+        reset: bool = True,
+        secondary_log_colors: Any = None,
+        add_timestamp: bool = False,
+    ) -> None:
+        super().__init__(
+            fmt=_get_format(colorlog=True, add_timestamp=add_timestamp),
+            datefmt=datefmt,
+            style=style,
+            log_colors=log_colors,
+            reset=reset,
+            secondary_log_colors=secondary_log_colors,
+        )
+
+    def format(self, record: Any) -> str:
+        if record.levelname == "OUTPUT":
+            return self._simple_fmt.format(record)
+        return super().format(record)
 
 
 class LoggerWithSuccessAndOutput(logging.getLoggerClass()):  # type: ignore
@@ -55,23 +93,9 @@ logging.setLoggerClass(LoggerWithSuccessAndOutput)
 logger = cast(LoggerWithSuccessAndOutput, logging.getLogger("nox"))
 
 
-def setup_logging(color: bool, verbose: bool = False) -> None:  # pragma: no cover
-    """Setup logging.
-
-    Args:
-        color (bool): If true, the output will be colored using
-            colorlog. Otherwise, it will be plaintext.
-    """
-    root_logger = logging.getLogger()
-    if verbose:
-        root_logger.setLevel(OUTPUT)
-    else:
-        root_logger.setLevel(logging.DEBUG)
-    handler = logging.StreamHandler()
-
+def _get_formatter(color: bool, add_timestamp: bool) -> logging.Formatter:
     if color is True:
-        formatter = NoxFormatter(
-            "%(cyan)s%(name)s > %(log_color)s%(message)s",
+        return NoxColoredFormatter(
             reset=True,
             log_colors={
                 "DEBUG": "cyan",
@@ -81,10 +105,31 @@ def setup_logging(color: bool, verbose: bool = False) -> None:  # pragma: no cov
                 "CRITICAL": "red,bg_white",
                 "SUCCESS": "green",
             },
+            style="%",
+            secondary_log_colors=None,
+            add_timestamp=add_timestamp,
         )
+    else:
+        return NoxFormatter(add_timestamp=add_timestamp)
+
 
-        handler.setFormatter(formatter)
+def setup_logging(
+    color: bool, verbose: bool = False, add_timestamp: bool = False
+) -> None:  # pragma: no cover
+    """Setup logging.
+
+    Args:
+        color (bool): If true, the output will be colored using
+            colorlog. Otherwise, it will be plaintext.
+    """
+    root_logger = logging.getLogger()
+    if verbose:
+        root_logger.setLevel(OUTPUT)
+    else:
+        root_logger.setLevel(logging.DEBUG)
+    handler = logging.StreamHandler()
 
+    handler.setFormatter(_get_formatter(color, add_timestamp))
     root_logger.addHandler(handler)
 
     # Silence noisy loggers


Test patch:
diff --git a/tests/test_logger.py b/tests/test_logger.py
index 9d8b6fc..eef9dcf 100644
--- a/tests/test_logger.py
+++ b/tests/test_logger.py
@@ -15,6 +15,8 @@
 import logging
 from unittest import mock
 
+import pytest
+
 from nox import logger
 
 
@@ -39,6 +41,7 @@ def test_formatter(caplog):
 
     logs = [rec for rec in caplog.records if rec.levelname in ("INFO", "OUTPUT")]
     assert len(logs) == 1
+    assert not hasattr(logs[0], "asctime")
 
     caplog.clear()
     with caplog.at_level(logger.OUTPUT):
@@ -52,3 +55,38 @@ def test_formatter(caplog):
     assert len(logs) == 1
     # Make sure output level log records are not nox prefixed
     assert "nox" not in logs[0].message
+
+
+@pytest.mark.parametrize(
+    "color",
+    [
+        # This currently fails due to some incompatibility between caplog and colorlog
+        # that causes caplog to not collect the asctime from colorlog.
+        pytest.param(True, id="color", marks=pytest.mark.xfail),
+        pytest.param(False, id="no-color"),
+    ],
+)
+def test_no_color_timestamp(caplog, color):
+    logger.setup_logging(color=color, add_timestamp=True)
+    caplog.clear()
+    with caplog.at_level(logging.DEBUG):
+        logger.logger.info("bar")
+        logger.logger.output("foo")
+
+    logs = [rec for rec in caplog.records if rec.levelname in ("INFO", "OUTPUT")]
+    assert len(logs) == 1
+    assert hasattr(logs[0], "asctime")
+
+    caplog.clear()
+    with caplog.at_level(logger.OUTPUT):
+        logger.logger.info("bar")
+        logger.logger.output("foo")
+
+    logs = [rec for rec in caplog.records if rec.levelname != "OUTPUT"]
+    assert len(logs) == 1
+    assert hasattr(logs[0], "asctime")
+
+    logs = [rec for rec in caplog.records if rec.levelname == "OUTPUT"]
+    assert len(logs) == 1
+    # no timestamp for output
+    assert not hasattr(logs[0], "asctime")