Improve PipTestEnvironment to check for logging errors.

Author: cjerdonek

tests/lib/__init__.py

@@ -1,6 +1,7 @@
 from __future__ import absolute_import
 
 from contextlib import contextmanager
+from textwrap import dedent
 import os
 import sys
 import re
@@ -263,6 +264,17 @@ def assert_installed(self, pkg_name, editable=True, with_files=[],
                 )
 
 
+def make_check_stderr_message(stderr, line, reason):
+    """
+    Create an exception message to use inside check_stderr().
+    """
+    return dedent("""\
+    {reason}:
+     Caused by line: {line!r}
+     Complete stderr: {stderr}
+    """).format(stderr=stderr, line=line, reason=reason)
+
+
 def check_stderr(
     stderr, allow_stderr_warning=None, allow_stderr_error=None,
 ):
@@ -293,22 +305,34 @@ def check_stderr(
 
     lines = stderr.splitlines()
     for line in lines:
+        # First check for logging errors which are sent directly to stderr
+        # and so bypass any configured log formatter.  The
+        # "--- Logging error ---" string is used in Python 3.4+, and
+        # "Logged from file " is used in Python 2.
+        if (line.startswith('--- Logging error ---') or
+                line.startswith('Logged from file ')):
+            reason = 'stderr has a logging error, which is never allowed'
+            msg = make_check_stderr_message(stderr, line=line, reason=reason)
+            raise RuntimeError(msg)
+
         if line.startswith('ERROR: '):
-            raise RuntimeError(
+            reason = (
                 'stderr has an unexpected error '
-                '(pass allow_stderr_error=True to permit this): {}'
-                .format(line)
+                '(pass allow_stderr_error=True to permit this)'
             )
+            msg = make_check_stderr_message(stderr, line=line, reason=reason)
+            raise RuntimeError(msg)
         if allow_stderr_warning:
             continue
 
         if (line.startswith('WARNING: ') or
                 line.startswith(DEPRECATION_MSG_PREFIX)):
-            raise RuntimeError(
+            reason = (
                 'stderr has an unexpected warning '
-                '(pass allow_stderr_warning=True to permit this): {}'
-                .format(line)
+                '(pass allow_stderr_warning=True to permit this)'
             )
+            msg = make_check_stderr_message(stderr, line=line, reason=reason)
+            raise RuntimeError(msg)
 
 
 class PipTestEnvironment(TestFileEnvironment):

tests/lib/test_lib.py

@@ -20,7 +20,9 @@ def assert_error_startswith(exc_type, expected_start):
     with pytest.raises(exc_type) as err:
         yield
 
-    assert str(err.value).startswith(expected_start)
+    assert str(err.value).startswith(expected_start), (
+        'full message: {}'.format(err.value)
+    )
 
 
 def test_tmp_dir_exists_in_env(script):
@@ -78,6 +80,18 @@ def test_as_import(script):
 
 class TestPipTestEnvironment:
 
+    def run_with_log_command(self, script, sub_string):
+        """
+        Call run() on a command that logs a "%"-style format string using
+        the given substring as the string's replacement field.
+        """
+        command = (
+            "import logging; logging.basicConfig(level='INFO'); "
+            "logging.getLogger().info('sub: {}', 'foo')"
+        ).format(sub_string)
+        args = [sys.executable, '-c', command]
+        script.run(*args)
+
     def run_stderr_with_prefix(self, script, prefix, **kwargs):
         """
         Call run() that prints stderr with the given prefix.
@@ -139,6 +153,18 @@ def test_run__unexpected_stderr(self, script, prefix, expected_start):
         with assert_error_startswith(RuntimeError, expected_start):
             self.run_stderr_with_prefix(script, prefix)
 
+    def test_run__logging_error(self, script):
+        """
+        Test calling run() with an unexpected logging error.
+        """
+        # Pass a good substitution string.
+        self.run_with_log_command(script, sub_string='%r')
+
+        expected_start = 'stderr has a logging error, which is never allowed'
+        with assert_error_startswith(RuntimeError, expected_start):
+            # Pass a bad substitution string.
+            self.run_with_log_command(script, sub_string='{!r}')
+
     def test_run__allow_stderr_error_false_error_with_expect_error(
         self, script,
     ):