From e6d01279859d18a654a0b44113316096db374f37 Mon Sep 17 00:00:00 2001 From: Chris Jerdonek Date: Tue, 23 Oct 2018 00:46:43 -0700 Subject: [PATCH 1/3] Add failing tests. --- src/pip/_internal/utils/logging.py | 7 ++ src/pip/_internal/utils/misc.py | 7 ++ tests/functional/test_broken_stdout.py | 65 +++++++++++++++++ tests/unit/test_base_command.py | 47 ++++++++++-- tests/unit/test_logging.py | 99 +++++++++++++++++++++++++- 5 files changed, 220 insertions(+), 5 deletions(-) create mode 100644 tests/functional/test_broken_stdout.py diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index bc8b5fbd7..a12c21e6c 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -26,6 +26,13 @@ _log_state = threading.local() _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): """ diff --git a/src/pip/_internal/utils/misc.py b/src/pip/_internal/utils/misc.py index bb6e51517..84605ee36 100644 --- a/src/pip/_internal/utils/misc.py +++ b/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 diff --git a/tests/functional/test_broken_stdout.py b/tests/functional/test_broken_stdout.py new file mode 100644 index 000000000..788ab3a3c --- /dev/null +++ b/tests/functional/test_broken_stdout.py @@ -0,0 +1,65 @@ +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: + # 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() + # This line causes a timeout on Windows. + 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 + + +@pytest.mark.skipif(WINDOWS, reason="test times out on Windows") +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 + + +@pytest.mark.skipif(WINDOWS, reason="test times out on Windows") +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 diff --git a/tests/unit/test_base_command.py b/tests/unit/test_base_command.py index c64143629..e25df4a80 100644 --- a/tests/unit/test_base_command.py +++ b/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 diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index e2f407e36..af70f568f 100644 --- a/tests/unit/test_logging.py +++ b/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') From 7a9e1f344b6b24a737b5076a2161add1cedffb89 Mon Sep 17 00:00:00 2001 From: Chris Jerdonek Date: Tue, 23 Oct 2018 01:55:07 -0700 Subject: [PATCH 2/3] Handle BrokenPipeError gracefully. --- news/4170.bugfix | 1 + src/pip/_internal/cli/base_command.py | 13 ++++++-- src/pip/_internal/utils/logging.py | 44 +++++++++++++++++++++++++++ 3 files changed, 56 insertions(+), 2 deletions(-) create mode 100644 news/4170.bugfix diff --git a/news/4170.bugfix b/news/4170.bugfix new file mode 100644 index 000000000..a8e8d07b2 --- /dev/null +++ b/news/4170.bugfix @@ -0,0 +1 @@ +Handle a broken stdout pipe more gracefully (e.g. when running ``pip list | head``). diff --git a/src/pip/_internal/cli/base_command.py b/src/pip/_internal/cli/base_command.py index a4b6aa1ef..8a602bab4 100644 --- a/src/pip/_internal/cli/base_command.py +++ b/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') diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index a12c21e6c..5776fc9fd 100644 --- a/src/pip/_internal/utils/logging.py +++ b/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 @@ -33,6 +37,23 @@ class BrokenStdoutLoggingError(Exception): pass +if PY2: + # BrokenPipeError does not exist in Python 2. + 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 IOError and exc.errno == errno.EPIPE) + +else: + def _is_broken_pipe_error(exc_class, exc): + return (exc_class is BrokenPipeError) # noqa: F821 + + @contextlib.contextmanager def indent_log(num=2): """ @@ -103,6 +124,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: @@ -135,6 +166,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): From eef02fd6665ab8d4fd8bbed9dd70447f67386143 Mon Sep 17 00:00:00 2001 From: Chris Jerdonek Date: Wed, 16 Jan 2019 01:51:25 -0800 Subject: [PATCH 3/3] Unskip / get the end-to-end tests working for Windows. --- src/pip/_internal/utils/logging.py | 30 ++++++++++++++++++++------ tests/functional/test_broken_stdout.py | 7 ------ 2 files changed, 24 insertions(+), 13 deletions(-) diff --git a/src/pip/_internal/utils/logging.py b/src/pip/_internal/utils/logging.py index 5776fc9fd..a86aaf1df 100644 --- a/src/pip/_internal/utils/logging.py +++ b/src/pip/_internal/utils/logging.py @@ -37,8 +37,30 @@ class BrokenStdoutLoggingError(Exception): pass -if PY2: - # BrokenPipeError does not exist in Python 2. +# 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. @@ -47,10 +69,6 @@ if PY2: exc_class: an exception class. exc: an exception instance. """ - return (exc_class is IOError and exc.errno == errno.EPIPE) - -else: - def _is_broken_pipe_error(exc_class, exc): return (exc_class is BrokenPipeError) # noqa: F821 diff --git a/tests/functional/test_broken_stdout.py b/tests/functional/test_broken_stdout.py index 788ab3a3c..afb66f5a5 100644 --- a/tests/functional/test_broken_stdout.py +++ b/tests/functional/test_broken_stdout.py @@ -1,10 +1,6 @@ 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: @@ -19,7 +15,6 @@ def setup_broken_stdout_test(args, deprecated_python): ) # 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') @@ -32,7 +27,6 @@ def setup_broken_stdout_test(args, deprecated_python): return stderr, returncode -@pytest.mark.skipif(WINDOWS, reason="test times out on Windows") def test_broken_stdout_pipe(deprecated_python): """ Test a broken pipe to stdout. @@ -48,7 +42,6 @@ def test_broken_stdout_pipe(deprecated_python): assert returncode == _BROKEN_STDOUT_RETURN_CODE -@pytest.mark.skipif(WINDOWS, reason="test times out on Windows") def test_broken_stdout_pipe__verbose(deprecated_python): """ Test a broken pipe to stdout with verbose logging enabled.