[Failing test] ColoredLogsTestCase.test_plain_text_output_format

[mcepl]

[   60s] + py.test-3.7 coloredlogs/tests.py -v -k 'not (test_cli_conversion or test_auto_install)'
[   61s] ============================= test session starts ==============================
[   61s] platform linux -- Python 3.7.2, pytest-3.10.1, py-1.7.0, pluggy-0.8.0 -- /usr/bin/python3
[   61s] cachedir: .pytest_cache
[   61s] rootdir: /home/abuild/rpmbuild/BUILD/coloredlogs-10.0, inifile:
[   61s] plugins: cov-2.6.0
...
[   61s] =================================== FAILURES ===================================
[   61s] ______________ ColoredLogsTestCase.test_plain_text_output_format _______________
[   61s] 
[   61s] self = <coloredlogs.tests.ColoredLogsTestCase testMethod=test_plain_text_output_format>
[   61s] test_method = <bound method ColoredLogsTestCase.test_plain_text_output_format of <coloredlogs.tests.ColoredLogsTestCase testMethod=test_plain_text_output_format>>
[   61s] args = (), kw = {}
[   61s] 
[   61s]     def skipTestWrapper(self, test_method, *args, **kw):
[   61s]         """
[   61s]         Wrap test methods to translate exceptions into skipped tests.
[   61s]     
[   61s]         :param test_method: The test method to wrap.
[   61s]         :param args: The positional arguments to the test method.
[   61s]         :param kw: The keyword arguments to the test method.
[   61s]         :returns: The return value of the test method.
[   61s]     
[   61s]         When a :class:`TestCase` object is initialized, :func:`__init__()`
[   61s]         wraps all of the ``test_*`` methods with :func:`skipTestWrapper()`.
[   61s]     
[   61s]         When a test method raises an exception, :func:`skipTestWrapper()` will
[   61s]         catch the exception and call :func:`shouldSkipTest()` to decide whether
[   61s]         to translate the exception into a skipped test.
[   61s]     
[   61s]         When :func:`shouldSkipTest()` returns :data:`True` the exception is
[   61s]         swallowed and :exc:`unittest.SkipTest` is raised instead of the
[   61s]         original exception.
[   61s]         """
[   61s]         try:
[   61s] >           return test_method(*args, **kw)
[   61s] 
[   61s] /usr/lib/python3.7/site-packages/humanfriendly/testing.py:678: 
[   61s] _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[   61s] 
[   61s] self = <coloredlogs.tests.ColoredLogsTestCase testMethod=test_plain_text_output_format>
[   61s] 
[   61s]     def test_plain_text_output_format(self):
[   61s]         """Inspect the plain text output of coloredlogs."""
[   61s]         logger = VerboseLogger(random_string(25))
[   61s]         stream = StringIO()
[   61s]         install(level=logging.NOTSET, logger=logger, stream=stream)
[   61s]         # Test that filtering on severity works.
[   61s]         logger.setLevel(logging.INFO)
[   61s]         logger.debug("No one should see this message.")
[   61s]         assert len(stream.getvalue().strip()) == 0
[   61s]         # Test that the default output format looks okay in plain text.
[   61s]         logger.setLevel(logging.NOTSET)
[   61s]         for method, severity in ((logger.debug, 'DEBUG'),
[   61s]                                  (logger.info, 'INFO'),
[   61s]                                  (logger.verbose, 'VERBOSE'),
[   61s]                                  (logger.warning, 'WARNING'),
[   61s]                                  (logger.error, 'ERROR'),
[   61s]                                  (logger.critical, 'CRITICAL')):
[   61s]             # Prepare the text.
[   61s]             text = "This is a message with severity %r." % severity.lower()
[   61s]             # Log the message with the given severity.
[   61s]             method(text)
[   61s]             # Get the line of output generated by the handler.
[   61s]             output = stream.getvalue()
[   61s]             lines = output.splitlines()
[   61s] >           last_line = lines[-1]
[   61s] E           IndexError: list index out of range
[   61s] 
[   61s] coloredlogs/tests.py:396: IndexError
[   61s] ----------------------------- Captured stderr call -----------------------------
[   61s]

Official package for openSUSE/Tumbleweed.

[cottsay]

I'm seeing this same error during official packaging for Fedora on Python 3.7 as well. It appears that once a logging event occurs, the level can't be changed.

[xolox]

I enabled Python 3.7 testing on Travis CI earlier today and was disappointed to run into the same test failure that is mentioned here. I then spent way too much of my time to get to the root cause (before I had read this issue).

This is definitely caused by a regression in behavior from Python 3.6 to 3.7, in fact I'm inclined to call it a bug, but I'm not sure if anyone cares (log levels don't usually change much). The issue is caused by isEnabledFor() using a stale (level, enabled) cache entry.

For now I've added a workaround to the test suite (cc41bf1) that clears the cache inside of the affected test, resolving the immediate issue. This was the only Python 3.7 incompatibility.

I'm going to close this issue now, given that the test suite now passes on Python 3.7. The fix is included in coloredlogs 11.0 (released earlier today).