initial pass, some tests failing

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(

nox/_options.py

@@ -264,6 +264,14 @@ def _session_completer(
         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",

nox/logger.py

@@ -13,23 +13,61 @@
 # limitations under the License.
 
 import logging
-from typing import Any, cast
+from typing import Any, cast, Optional
 
 from colorlog import ColoredFormatter
 
 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):
+    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=None,
+        style=None,
+        log_colors=None,
+        reset=True,
+        secondary_log_colors=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,7 +93,9 @@ def output(self, msg: str, *args: Any, **kwargs: Any) -> None:
 logger = cast(LoggerWithSuccessAndOutput, logging.getLogger("nox"))
 
 
-def setup_logging(color: bool, verbose: bool = False) -> None:  # pragma: no cover
+def setup_logging(
+    color: bool, verbose: bool = False, add_timestamp: bool = False
+) -> None:  # pragma: no cover
     """Setup logging.
 
     Args:
@@ -68,10 +108,8 @@ def setup_logging(color: bool, verbose: bool = False) -> None:  # pragma: no cov
     else:
         root_logger.setLevel(logging.DEBUG)
     handler = logging.StreamHandler()
-
     if color is True:
-        formatter = NoxFormatter(
-            "%(cyan)s%(name)s > %(log_color)s%(message)s",
+        formatter = NoxColoredFormatter(
             reset=True,
             log_colors={
                 "DEBUG": "cyan",
@@ -81,9 +119,13 @@ 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,
         )
-
-        handler.setFormatter(formatter)
+    else:
+        formatter = NoxFormatter(add_timestamp=add_timestamp)
+    handler.setFormatter(formatter)
 
     root_logger.addHandler(handler)
 

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")