Merge pull request #5907 from cjerdonek/broken-pipe-error

Handle BrokenPipeError gracefully (#4170)

news/4170.bugfix

@@ -0,0 +1 @@
+Handle a broken stdout pipe more gracefully (e.g. when running ``pip list | head``).

src/pip/_internal/cli/base_command.py

@@ -1,11 +1,12 @@
 """Base Command class, and related routines"""
-from __future__ import absolute_import
+from __future__ import absolute_import, print_function
 
 import logging
 import logging.config
 import optparse
 import os
 import sys
+import traceback
 
 from pip._internal.cli import cmdoptions
 from pip._internal.cli.parser import (
@@ -27,7 +28,7 @@ from pip._internal.req.constructors import (
 )
 from pip._internal.req.req_file import parse_requirements
 from pip._internal.utils.deprecation import deprecated
-from pip._internal.utils.logging import setup_logging
+from pip._internal.utils.logging import BrokenStdoutLoggingError, setup_logging
 from pip._internal.utils.misc import (
     get_prog, normalize_path, redact_password_from_url,
 )
@@ -191,6 +192,14 @@ class Command(object):
             logger.critical('ERROR: %s', exc)
             logger.debug('Exception information:', exc_info=True)
 
+            return ERROR
+        except BrokenStdoutLoggingError:
+            # Bypass our logger and write any remaining messages to stderr
+            # because stdout no longer works.
+            print('ERROR: Pipe to stdout was broken', file=sys.stderr)
+            if logger.getEffectiveLevel() <= logging.DEBUG:
+                traceback.print_exc(file=sys.stderr)
+
             return ERROR
         except KeyboardInterrupt:
             logger.critical('Operation cancelled by user')

src/pip/_internal/utils/logging.py

@@ -1,9 +1,13 @@
 from __future__ import absolute_import
 
 import contextlib
+import errno
 import logging
 import logging.handlers
 import os
+import sys
+
+from pip._vendor.six import PY2
 
 from pip._internal.utils.compat import WINDOWS
 from pip._internal.utils.misc import ensure_dir
@@ -26,6 +30,48 @@ _log_state = threading.local()
 _log_state.indentation = 0
 
 
+class BrokenStdoutLoggingError(Exception):
+    """
+    Raised if BrokenPipeError occurs for the stdout stream while logging.
+    """
+    pass
+
+
+# BrokenPipeError does not exist in Python 2 and, in addition, manifests
+# differently in Windows and non-Windows.
+if WINDOWS:
+    # In Windows, a broken pipe can show up as EINVAL rather than EPIPE:
+    # https://bugs.python.org/issue19612
+    # https://bugs.python.org/issue30418
+    if PY2:
+        def _is_broken_pipe_error(exc_class, exc):
+            """See the docstring for non-Windows Python 3 below."""
+            return (exc_class is IOError and
+                    exc.errno in (errno.EINVAL, errno.EPIPE))
+    else:
+        # In Windows, a broken pipe IOError became OSError in Python 3.
+        def _is_broken_pipe_error(exc_class, exc):
+            """See the docstring for non-Windows Python 3 below."""
+            return ((exc_class is BrokenPipeError) or  # noqa: F821
+                    (exc_class is OSError and
+                     exc.errno in (errno.EINVAL, errno.EPIPE)))
+elif PY2:
+    def _is_broken_pipe_error(exc_class, exc):
+        """See the docstring for non-Windows Python 3 below."""
+        return (exc_class is IOError and exc.errno == errno.EPIPE)
+else:
+    # Then we are in the non-Windows Python 3 case.
+    def _is_broken_pipe_error(exc_class, exc):
+        """
+        Return whether an exception is a broken pipe error.
+
+        Args:
+          exc_class: an exception class.
+          exc: an exception instance.
+        """
+        return (exc_class is BrokenPipeError)  # noqa: F821
+
+
 @contextlib.contextmanager
 def indent_log(num=2):
     """
@@ -96,6 +142,16 @@ class ColorizedStreamHandler(logging.StreamHandler):
         if WINDOWS and colorama:
             self.stream = colorama.AnsiToWin32(self.stream)
 
+    def _using_stdout(self):
+        """
+        Return whether the handler is using sys.stdout.
+        """
+        if WINDOWS and colorama:
+            # Then self.stream is an AnsiToWin32 object.
+            return self.stream.wrapped is sys.stdout
+
+        return self.stream is sys.stdout
+
     def should_color(self):
         # Don't colorize things if we do not have colorama or if told not to
         if not colorama or self._no_color:
@@ -128,6 +184,19 @@ class ColorizedStreamHandler(logging.StreamHandler):
 
         return msg
 
+    # The logging module says handleError() can be customized.
+    def handleError(self, record):
+        exc_class, exc = sys.exc_info()[:2]
+        # If a broken pipe occurred while calling write() or flush() on the
+        # stdout stream in logging's Handler.emit(), then raise our special
+        # exception so we can handle it in main() instead of logging the
+        # broken pipe error and continuing.
+        if (exc_class and self._using_stdout() and
+                _is_broken_pipe_error(exc_class, exc)):
+            raise BrokenStdoutLoggingError()
+
+        return super(ColorizedStreamHandler, self).handleError(record)
+
 
 class BetterRotatingFileHandler(logging.handlers.RotatingFileHandler):
 

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,58 @@
+import subprocess
+import sys
+
+if sys.version_info < (3, 6):
+    _BROKEN_STDOUT_RETURN_CODE = 1
+else:
+    # The new exit status was added in Python 3.6 as a result of:
+    # https://bugs.python.org/issue5319
+    _BROKEN_STDOUT_RETURN_CODE = 120
+
+
+def setup_broken_stdout_test(args, deprecated_python):
+    proc = subprocess.Popen(
+        args, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
+    )
+    # Call close() on stdout to cause a broken pipe.
+    proc.stdout.close()
+    returncode = proc.wait()
+    stderr = proc.stderr.read().decode('utf-8')
+
+    expected_msg = 'ERROR: Pipe to stdout was broken'
+    if deprecated_python:
+        assert expected_msg in stderr
+    else:
+        assert stderr.startswith(expected_msg)
+
+    return stderr, returncode
+
+
+def test_broken_stdout_pipe(deprecated_python):
+    """
+    Test a broken pipe to stdout.
+    """
+    stderr, returncode = setup_broken_stdout_test(
+        ['pip', 'list'], deprecated_python=deprecated_python,
+    )
+
+    # Check that no traceback occurs.
+    assert 'raise BrokenStdoutLoggingError()' not in stderr
+    assert stderr.count('Traceback') == 0
+
+    assert returncode == _BROKEN_STDOUT_RETURN_CODE
+
+
+def test_broken_stdout_pipe__verbose(deprecated_python):
+    """
+    Test a broken pipe to stdout with verbose logging enabled.
+    """
+    stderr, returncode = setup_broken_stdout_test(
+        ['pip', '-v', 'list'], deprecated_python=deprecated_python,
+    )
+
+    # 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

@@ -3,14 +3,19 @@ import os
 import time
 
 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):
@@ -19,8 +24,8 @@ class FakeCommand(Command):
 
     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):
@@ -34,6 +39,40 @@ class FakeCommandWithUnicode(FakeCommand):
         )
 
 
+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

@@ -1,8 +1,31 @@
+import errno
 import logging
 import os
 import time
 
-from pip._internal.utils.logging import IndentingFormatter
+import pytest
+from mock import patch
+from pip._vendor.six import PY2
+
+from pip._internal.utils.logging import (
+    BrokenStdoutLoggingError, ColorizedStreamHandler, IndentingFormatter,
+)
+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 representing a broken pipe.
+    """
+    if PY2:
+        # This is one way a broken pipe error can show up in Python 2
+        # (a non-Windows example in this case).
+        return IOError(errno.EPIPE, 'Broken pipe')
+
+    return BrokenPipeError()  # noqa: F821
 
 
 class TestIndentingFormatter(object):
@@ -43,3 +66,77 @@ class TestIndentingFormatter(object):
         f = IndentingFormatter(fmt="%(message)s", add_timestamp=True)
         expected = '2019-01-17T06:00:37 hello\n2019-01-17T06:00:37 world'
         assert f.format(record) == expected
+
+
+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')