Add --verbose for showing the output from all commands (#174)

* Allow the commands output to be logged by passing `--verbose` to nox

* Add test case to confirm commout output when verbose is set

docs/usage.rst

@@ -261,6 +261,13 @@ However, this will never output colorful logs:
 .. _opt-report:
 
 
+Controling commands verbosity
+-----------------------------
+
+By default, Nox will only show output of commands that fail, or, when the commands get passed `silent=False`.
+By passing `--verbose` to Nox, all output of all commands run is shown, regardless of the silent argument.
+
+
 Outputting a machine-readable report
 ------------------------------------
 

nox/__main__.py

@@ -41,7 +41,7 @@ def main():
         print(dist.version, file=sys.stderr)
         return
 
-    setup_logging(color=args.color)
+    setup_logging(color=args.color, verbose=args.verbose)
 
     # Execute the appropriate tasks.
     exit_code = workflow.execute(

nox/_options.py

@@ -187,6 +187,15 @@ def _session_completer(prefix, parsed_args, **kwargs):
         help="Arguments following ``--`` that are passed through to the session(s).",
         finalizer_func=_posargs_finalizer,
     ),
+    _option_set.Option(
+        "verbose",
+        "-v",
+        "--verbose",
+        group="secondary",
+        action="store_true",
+        help="Logs the output of all commands run including commands marked silent.",
+        noxfile=True,
+    ),
     *_option_set.make_flag_pair(
         "reuse_existing_virtualenvs",
         ("-r", "--reuse-existing-virtualenvs"),

nox/command.py

@@ -122,6 +122,9 @@ def run(
 
             raise CommandFailed("Returned code {}".format(return_code))
 
+        if output:
+            logger.output(output)
+
         return output if silent else True
 
     except KeyboardInterrupt:

nox/logger.py

@@ -17,38 +17,59 @@
 from colorlog import ColoredFormatter  # type: ignore
 
 SUCCESS = 25
+OUTPUT = logging.DEBUG - 1
 
 
-class LoggerWithSuccess(logging.getLoggerClass()):  # type: ignore
+class NoxFormatter(ColoredFormatter):
+    def __init__(self, *args, **kwargs):
+        super(NoxFormatter, self).__init__(*args, **kwargs)
+        self._simple_fmt = logging.Formatter("%(message)s")
+
+    def format(self, record):
+        if record.levelname == "OUTPUT":
+            return self._simple_fmt.format(record)
+        return super(NoxFormatter, self).format(record)
+
+
+class LoggerWithSuccessAndOutput(logging.getLoggerClass()):  # type: ignore
     def __init__(self, name, level=logging.NOTSET):
-        super(LoggerWithSuccess, self).__init__(name, level)
+        super(LoggerWithSuccessAndOutput, self).__init__(name, level)
         logging.addLevelName(SUCCESS, "SUCCESS")
+        logging.addLevelName(OUTPUT, "OUTPUT")
 
     def success(self, msg, *args, **kwargs):
         if self.isEnabledFor(SUCCESS):
             self._log(SUCCESS, msg, args, **kwargs)
         else:  # pragma: no cover
             pass
 
+    def output(self, msg, *args, **kwargs):
+        if self.isEnabledFor(OUTPUT):
+            self._log(OUTPUT, msg, args, **kwargs)
+        else:  # pragma: no cover
+            pass
+
 
-logging.setLoggerClass(LoggerWithSuccess)
+logging.setLoggerClass(LoggerWithSuccessAndOutput)
 logger = logging.getLogger("nox")
-logger.setLevel(logging.DEBUG)
 
 
-def setup_logging(color):  # pragma: no cover
+def setup_logging(color, verbose=False):  # 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()
-    root_logger.setLevel(logging.DEBUG)
+    if verbose:
+        root_logger.setLevel(OUTPUT)
+    else:
+        root_logger.setLevel(logging.DEBUG)
     handler = logging.StreamHandler()
 
     if color is True:
-        formatter = ColoredFormatter(
+        formatter = NoxFormatter(
             "%(cyan)s%(name)s > %(log_color)s%(message)s",
             reset=True,
             log_colors={

tests/test_command.py

@@ -39,6 +39,61 @@ def test_run_silent(capsys):
     assert out == ""
 
 
+def test_run_verbosity(capsys, caplog):
+    caplog.clear()
+    with caplog.at_level(logging.DEBUG):
+        result = nox.command.run([PYTHON, "-c", "print(123)"], silent=True)
+
+        out, _ = capsys.readouterr()
+
+        assert "123" in result
+        assert out == ""
+
+    logs = [rec for rec in caplog.records if rec.levelname == "OUTPUT"]
+    assert not logs
+
+    caplog.clear()
+    with caplog.at_level(logging.DEBUG - 1):
+        result = nox.command.run([PYTHON, "-c", "print(123)"], silent=True)
+
+        out, _ = capsys.readouterr()
+
+        assert "123" in result
+        assert out == ""
+
+    logs = [rec for rec in caplog.records if rec.levelname == "OUTPUT"]
+    assert logs
+    assert logs[0].message.strip() == "123"
+
+
+def test_run_verbosity_failed_command(capsys, caplog):
+    caplog.clear()
+    with caplog.at_level(logging.DEBUG):
+        with pytest.raises(nox.command.CommandFailed):
+            nox.command.run([PYTHON, "-c", "print(123); exit(1)"], silent=True)
+
+        out, err = capsys.readouterr()
+
+        assert "123" in err
+        assert out == ""
+
+    logs = [rec for rec in caplog.records if rec.levelname == "OUTPUT"]
+    assert not logs
+
+    caplog.clear()
+    with caplog.at_level(logging.DEBUG - 1):
+        with pytest.raises(nox.command.CommandFailed):
+            nox.command.run([PYTHON, "-c", "print(123); exit(1)"], silent=True)
+
+        out, err = capsys.readouterr()
+
+        assert "123" in err
+        assert out == ""
+
+    # Nothing is logged but the error is still written to stderr
+    assert not logs
+
+
 def test_run_env_unicode():
     result = nox.command.run(
         [PYTHON, "-c", 'import os; print(os.environ["SIGIL"])'],

tests/test_logger.py

@@ -12,12 +12,43 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import logging
 from unittest import mock
 
 from nox import logger
 
 
 def test_success():
-    with mock.patch.object(logger.LoggerWithSuccess, "_log") as _log:
-        logger.LoggerWithSuccess("foo").success("bar")
+    with mock.patch.object(logger.LoggerWithSuccessAndOutput, "_log") as _log:
+        logger.LoggerWithSuccessAndOutput("foo").success("bar")
         _log.assert_called_once_with(logger.SUCCESS, "bar", ())
+
+
+def test_output():
+    with mock.patch.object(logger.LoggerWithSuccessAndOutput, "_log") as _log:
+        logger.LoggerWithSuccessAndOutput("foo").output("bar")
+        _log.assert_called_once_with(logger.OUTPUT, "bar", ())
+
+
+def test_formatter(caplog):
+    caplog.clear()
+    logger.setup_logging(True, verbose=True)
+    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
+
+    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 in ("INFO", "OUTPUT")]
+    assert len(logs) == 2
+
+    logs = [rec for rec in caplog.records if rec.levelname == "OUTPUT"]
+    assert len(logs) == 1
+    # Make sure output level log records are not nox prefixed
+    assert "nox" not in logs[0].message