Problem with CliRunner and Python's logging module

[iLoveTux]

If I have a click.command instance which calls logging.basicConfig with stream=sys.stdout and I use an instance of click.CliRunner to test the output that the command produces more than once it will fail after the first test.

import sys
import click
import logging
import unittest
from click.testing import CliRunner

@click.command()
@click.argument("name")
def greet(name):
    logging.basicConfig(stream=sys.stdout, level=10)
    logging.info('hello, {}!'.format(name))

class TestCli(unittest.TestCase):
    """Both tests are exactly the same"""
    def test_greet_1(self):
        runner = CliRunner()
        result = runner.invoke(greet, ["world"])
        self.assertEqual(result.exit_code, 0)
        self.assertIn('hello, world', result.output)

    def test_cli_2(self):
        runner = CliRunner()
        result = runner.invoke(greet, ["world"])
        self.assertEqual(result.exit_code, 0)
        self.assertIn('hello, world', result.output)

if __name__ == "__main__":
    unittest.main()

See the results:

$ python test_CliRunner.py
.F
======================================================================
FAIL: test_greet_1 (__main__.TestCli)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "test_CliRunner.py", line 18, in test_greet_1
    self.assertIn('hello, world', result.output)
AssertionError: 'hello, world' not found in ''

----------------------------------------------------------------------
Ran 2 tests in 0.010s

FAILED (failures=1)

The best I can figure out is that CliRunner intercepts sys.stdout and replaces it with a file-like object. A handler is then attached to the root logger by a call to logging.basicConfig within the command.

When the command is invoked the second time, a new file-like object is allocated for sys.stdout but the handler referencing the original file-like object persists rendering the call to logging.basicConfig a no-op. This leads to failures of any tests that are examining the output of the command.

I have successfully worked around this issue with the following code:

import sys
import click
import logging
import unittest
from click.testing import CliRunner

@click.command()
@click.argument("name")
def greet(name):
    logging.basicConfig(stream=sys.stdout, level=10)
    logging.info('hello, {}!'.format(name))

class TestCli(unittest.TestCase):
    def setUp(self):
        logging.getLogger("").handlers = [] 

    def test_greet_1(self):
        runner = CliRunner()
        result = runner.invoke(greet, ["world"])
        self.assertEqual(result.exit_code, 0)
        self.assertIn('hello, world', result.output)

    def test_cli_2(self):
        runner = CliRunner()
        result = runner.invoke(greet, ["world"])
        self.assertEqual(result.exit_code, 0)
        self.assertIn('hello, world', result.output)

if __name__ == "__main__":
    unittest.main()

Notice the added setUp method which clears the root logger of any handlers so that the call to logging.basicConfig will attach to the current "sys.stdout".

The output is here:

$ python test_CliRunner.py
..
----------------------------------------------------------------------
Ran 2 tests in 0.008s

OK

Is there a better way to do this? Or are there better practices I could be using? Do you consider this to be a bug with click or just the way things work under the hood?

I'd be happy to help out if I knew what direction you wanted to take, but feel free to just close this issue because I was able to work around my issue.

[davidism]

This looks like a general issue with reproducible tests. If you do something that affects global state within a test, you need to reset that state after the test.

I don't think there's anything Click-specific that can be done here.