Add failing tests.

Author: cjerdonek

src/pip/_internal/utils/logging.py

@@ -26,6 +26,13 @@
 _log_state.indentation = 0
 
 
+class BrokenStdoutLoggingError(Exception):
+    """
+    Raised if BrokenPipeError occurs for the stdout stream while logging.
+    """
+    pass
+
+
 @contextlib.contextmanager
 def indent_log(num=2):
     """

src/pip/_internal/utils/misc.py

@@ -864,6 +864,13 @@ def captured_stdout():
     return captured_output('stdout')
 
 
+def captured_stderr():
+    """
+    See captured_stdout().
+    """
+    return captured_output('stderr')
+
+
 class cached_property(object):
     """A property that is only computed once per instance and then replaces
        itself with an ordinary attribute. Deleting the attribute resets the

tests/functional/test_broken_stdout.py

@@ -0,0 +1,60 @@
+import subprocess
+import sys
+
+import pytest
+
+from pip._internal.utils.compat import WINDOWS
+
+if sys.version_info < (3, 6):
+    _BROKEN_STDOUT_RETURN_CODE = 1
+else:
+    _BROKEN_STDOUT_RETURN_CODE = 120
+
+
+def setup_broken_stdout_test(args):
+    proc = subprocess.Popen(
+        args, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
+    )
+    # Call close() on stdout to cause a broken pipe.
+    proc.stdout.close()
+    # This line causes a timeout on Windows.
+    returncode = proc.wait()
+    stderr = proc.stderr.read().decode('utf-8')
+
+    if sys.version_info < (3, 5):
+        # In Python 3.4, stderr starts instead with--
+        # "DEPRECATION: Python 3.4 support has been deprecated..."
+        assert 'ERROR: Pipe to stdout was broken' in stderr
+    else:
+        assert stderr.startswith('ERROR: Pipe to stdout was broken')
+
+    return stderr, returncode
+
+
+@pytest.mark.skipif(WINDOWS, reason="test times out on Windows")
+def test_broken_stdout_pipe():
+    """
+    Test a broken pipe to stdout.
+    """
+    stderr, returncode = setup_broken_stdout_test(['pip', 'list'])
+
+    # Check that no traceback occurs.
+    assert 'raise BrokenStdoutLoggingError()' not in stderr
+    assert stderr.count('Traceback') == 0
+
+    assert returncode == _BROKEN_STDOUT_RETURN_CODE
+
+
+@pytest.mark.skipif(WINDOWS, reason="test times out on Windows")
+def test_broken_stdout_pipe__verbose():
+    """
+    Test a broken pipe to stdout with verbose logging enabled.
+    """
+    stderr, returncode = setup_broken_stdout_test(['pip', '-v', 'list'])
+
+    # Check that a traceback occurs and that it occurs at most once.
+    # We permit up to two because the exception can be chained.
+    assert 'raise BrokenStdoutLoggingError()' in stderr
+    assert 1 <= stderr.count('Traceback') <= 2
+
+    assert returncode == _BROKEN_STDOUT_RETURN_CODE

tests/unit/test_base_command.py

@@ -1,14 +1,19 @@
 import logging
 
 from pip._internal.cli.base_command import Command
+from pip._internal.utils.logging import BrokenStdoutLoggingError
 
 
 class FakeCommand(Command):
     name = 'fake'
     summary = name
 
-    def __init__(self, error=False):
-        self.error = error
+    def __init__(self, run_func=None, error=False):
+        if error:
+            def run_func():
+                raise SystemExit(1)
+
+        self.run_func = run_func
         super(FakeCommand, self).__init__()
 
     def main(self, args):
@@ -17,8 +22,8 @@ def main(self, args):
 
     def run(self, options, args):
         logging.getLogger("pip.tests").info("fake")
-        if self.error:
-            raise SystemExit(1)
+        if self.run_func:
+            return self.run_func()
 
 
 class FakeCommandWithUnicode(FakeCommand):
@@ -32,6 +37,40 @@ def run(self, options, args):
         )
 
 
+class TestCommand(object):
+
+    def call_main(self, capsys, args):
+        """
+        Call command.main(), and return the command's stderr.
+        """
+        def raise_broken_stdout():
+            raise BrokenStdoutLoggingError()
+
+        cmd = FakeCommand(run_func=raise_broken_stdout)
+        status = cmd.main(args)
+        assert status == 1
+        stderr = capsys.readouterr().err
+
+        return stderr
+
+    def test_raise_broken_stdout(self, capsys):
+        """
+        Test raising BrokenStdoutLoggingError.
+        """
+        stderr = self.call_main(capsys, [])
+
+        assert stderr.rstrip() == 'ERROR: Pipe to stdout was broken'
+
+    def test_raise_broken_stdout__debug_logging(self, capsys):
+        """
+        Test raising BrokenStdoutLoggingError with debug logging enabled.
+        """
+        stderr = self.call_main(capsys, ['-v'])
+
+        assert 'ERROR: Pipe to stdout was broken' in stderr
+        assert 'Traceback (most recent call last):' in stderr
+
+
 class Test_base_command_logging(object):
     """
     Test `pip.base_command.Command` setting up logging consumers based on

tests/unit/test_logging.py

@@ -0,0 +1,100 @@
+import errno
+import logging
+import sys
+
+import pytest
+from mock import patch
+from pip._vendor.six import PY2
+
+from pip._internal.utils.logging import (
+    BrokenStdoutLoggingError, ColorizedStreamHandler,
+)
+from pip._internal.utils.misc import captured_stderr, captured_stdout
+
+logger = logging.getLogger(__name__)
+
+
+# This is a Python 2/3 compatibility helper.
+def _make_broken_pipe_error():
+    """
+    Return an exception object for a broken pipe.
+    """
+    if sys.version_info[0] == 2:
+        # This is how BrokenPipeError shows up in Python 2.
+        return IOError(errno.EPIPE, 'Broken pipe')
+
+    return BrokenPipeError()  # noqa: F821
+
+
+class TestColorizedStreamHandler(object):
+
+    def _make_log_record(self):
+        attrs = {
+            'msg': 'my error',
+        }
+        record = logging.makeLogRecord(attrs)
+
+        return record
+
+    def test_broken_pipe_in_stderr_flush(self):
+        """
+        Test sys.stderr.flush() raising BrokenPipeError.
+
+        This error should _not_ trigger an error in the logging framework.
+        """
+        record = self._make_log_record()
+
+        with captured_stderr() as stderr:
+            handler = ColorizedStreamHandler(stream=stderr)
+            with patch('sys.stderr.flush') as mock_flush:
+                mock_flush.side_effect = _make_broken_pipe_error()
+                # The emit() call raises no exception.
+                handler.emit(record)
+
+            err_text = stderr.getvalue()
+
+        assert err_text.startswith('my error')
+        # Check that the logging framework tried to log the exception.
+        if PY2:
+            assert 'IOError: [Errno 32] Broken pipe' in err_text
+            assert 'Logged from file' in err_text
+        else:
+            assert 'Logging error' in err_text
+            assert 'BrokenPipeError' in err_text
+            assert "Message: 'my error'" in err_text
+
+    def test_broken_pipe_in_stdout_write(self):
+        """
+        Test sys.stdout.write() raising BrokenPipeError.
+
+        This error _should_ trigger an error in the logging framework.
+        """
+        record = self._make_log_record()
+
+        with captured_stdout() as stdout:
+            handler = ColorizedStreamHandler(stream=stdout)
+            with patch('sys.stdout.write') as mock_write:
+                mock_write.side_effect = _make_broken_pipe_error()
+                with pytest.raises(BrokenStdoutLoggingError):
+                    handler.emit(record)
+
+    def test_broken_pipe_in_stdout_flush(self):
+        """
+        Test sys.stdout.flush() raising BrokenPipeError.
+
+        This error _should_ trigger an error in the logging framework.
+        """
+        record = self._make_log_record()
+
+        with captured_stdout() as stdout:
+            handler = ColorizedStreamHandler(stream=stdout)
+            with patch('sys.stdout.flush') as mock_flush:
+                mock_flush.side_effect = _make_broken_pipe_error()
+                with pytest.raises(BrokenStdoutLoggingError):
+                    handler.emit(record)
+
+            output = stdout.getvalue()
+
+        # Sanity check that the log record was written, since flush() happens
+        # after write().
+        assert output.startswith('my error')