Repository: theacodes/nox
Pull request #174 (2019-03-16 12:08:09)

Allow showing the commands output
Refs #173 

s0undt3ch: This was the least intrusive approach but it means changing the only debug log call to info.
The alternative would be to introduce another log level.
Let me know if its preferred to go down that route.
theacodes: Hmm, I'm not sold on this approach. I don't like the idea of introducing a new flag (I'm *very* conservative about this).

What do you (and others) think about being able to just override the "silent" arg to `install`?

```python
session.install("requests", silent=False)
```
s0undt3ch: Since nox is pytest based, have you though about allowing noxfiles to extend the available CLI flags?
I know, off topic, but then again, not so much.
s0undt3ch: Also, to answer your question, with your suggestion you can either have it always on or off(the output).
I'm not interested on that output locally, but I am interested on that output in a CI context...
theacodes: Cool - this mostly looks good then, just one comment about using `logging` to output the content.
s0undt3ch: If we don't use logging we'll need to pass down the verbose flag to where we want verbose to be respected.
That's a whole lot of additional changes...
An additional verbose log level without the prefix you mention?
s0undt3ch: Do you want the verbose flag passed down?
theacodes: I like the idea of an additional verbose level that doesn't include the
prefix. We already extend the logger to add the "success" level.

On Sat, Mar 23, 2019, 7:23 AM Pedro Algarvio <notifications@github.com>
wrote:

> Do you want the verbose flag passed down?
>
> —
> You are receiving this because you commented.
>
>
> Reply to this email directly, view it on GitHub
> <https://github.com/theacodes/nox/pull/174#issuecomment-475873923>, or mute
> the thread
> <https://github.com/notifications/unsubscribe-auth/AAPUc1bGa6fIhdV6jV48wiWH9u2hlyd7ks5vZjjhgaJpZM4b3xR1>
> .
>

s0undt3ch: Ok. I'll go down that route.
erinwild-rubikloud: It's already possible to override the silent flag in session.install (see #157). If the desired outcome is conditional reporting particularly in a CI context, the function in the noxfile could potentially handle this via extra arguments.

For example, `nox -s tests -- verbose` when additional verbosity is desired:
```python
@nox.session(python='3.7')
def tests(session):
    verbosity = True if 'verbose' in session.posargs else False
    session.install('numpy', silent=verbosity)
```
s0undt3ch: True, but you won't get any output unless the command fails.
I'm after output even if the install command doesn't fail.
erinwild-rubikloud: I will verify it and update you but I’m fairly sure setting the silent flag means that it doesn’t have to fail for it to be printed. This is precisely what I was looking for when I submitted the PR.

It looks like there hasn’t been a release since then, so perhaps that’s all that needs to happen @theacodes
s0undt3ch: @erinwild-rubikloud you stand correct, passing `silent=False` shows the pip install output.
theacodes: I'm glad we got you what you need, but it may still be useful to have a
verbose mode that immediately turn on output for all of our "silent"
commands. Is this something you'd still be interested in adding?

On Thu, Apr 11, 2019, 8:18 AM Pedro Algarvio <notifications@github.com>
wrote:

> @erinwild-rubikloud <https://github.com/erinwild-rubikloud> you stand
> correct, passing silent=False shows the pip install output.
>
> —
> You are receiving this because you were mentioned.
> Reply to this email directly, view it on GitHub
> <https://github.com/theacodes/nox/pull/174#issuecomment-482158346>, or mute
> the thread
> <https://github.com/notifications/unsubscribe-auth/AAPUc6f8Tj9z_pLHBvm67SdltX3AZ4Rlks5vf1I9gaJpZM4b3xR1>
> .
>

s0undt3ch: Sure, I'll get back to it once I get some spare time.
s0undt3ch: Ready for another set of eyes
theacodes: This looks mostly good except for the one comment. Can you add documentation as well? (If not, I can amend the PR to do it.)
s0undt3ch: Applied suggestions.
theacodes: This LGTM, but I'm going to merge #187 and fix this up to use the new options pattern first. :)

It'll make it in before the next release.
theacodes: Okay, @s0undt3ch. I've rebased this to work with the changes for #187.

I *do* have an open question though: How does this handle cases such as `silent=True` and where the command fails?
s0undt3ch: @theacodes Nothing is logged but the error is printed to stderr.

Also, fixed conflict and rebased.
s0undt3ch: Conflicts resolved again.

Patch:
diff --git a/docs/usage.rst b/docs/usage.rst
index dc20034..6319682 100644
--- a/docs/usage.rst
+++ b/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
 ------------------------------------
 
diff --git a/nox/__main__.py b/nox/__main__.py
index 65f589f..c1f3ef0 100644
--- a/nox/__main__.py
+++ b/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(
diff --git a/nox/_options.py b/nox/_options.py
index 2d663da..a27d5e4 100644
--- a/nox/_options.py
+++ b/nox/_options.py
@@ -187,6 +187,15 @@ options.add_options(
         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"),
diff --git a/nox/command.py b/nox/command.py
index be00bbe..92db27f 100644
--- a/nox/command.py
+++ b/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:
diff --git a/nox/logger.py b/nox/logger.py
index 8ff2837..76a8ff9 100644
--- a/nox/logger.py
+++ b/nox/logger.py
@@ -17,12 +17,25 @@ import logging
 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):
@@ -30,13 +43,18 @@ class LoggerWithSuccess(logging.getLoggerClass()):  # type: ignore
         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:
@@ -44,11 +62,14 @@ def setup_logging(color):  # pragma: no cover
             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={


Test patch:
diff --git a/tests/test_command.py b/tests/test_command.py
index 39d5139..fb214f1 100644
--- a/tests/test_command.py
+++ b/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"])'],
diff --git a/tests/test_logger.py b/tests/test_logger.py
index 4893527..9d8b6fc 100644
--- a/tests/test_logger.py
+++ b/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