From 5bb9899938b229843194770045a23178aa3fc4b4 Mon Sep 17 00:00:00 2001 From: "Nathaniel J. Smith" Date: Wed, 4 Nov 2015 00:06:50 -0800 Subject: [PATCH] Display spinner during long setup.py calls One of the downsides of pip's new hiding of build chatter is that for packages that take a very long time to build (e.g. scipy) the user gets no indication that anything is happening for a very long time (e.g. tens of minutes), and is likely to get frustrated and hit Control-C. This can also create issues for automated systems that kill jobs that don't produce occasional output (e.g. Travis-CI). This commit implements an idea discussed here: https://github.com/pypa/pip/issues/2732#issuecomment-153215371 where we put up a spinner that rotates whenever the underlying build produces output. I tried it on scipy, and it the experience was quite pleasant! It spun around, sometimes fast and sometimes slow, and then there was one uncomfortable pause for ~1 minute while a very gnarly C++ file got compiled, but that's okay because it was actually providing accurate feedback. It looks like: ``` Running setup.py install for scipy ... / Running setup.py install for scipy ... - Running setup.py install for scipy ... \ Running setup.py install for scipy ... done ``` or if the command has non-zero return code, or an exception is raised, you get: ``` Running setup.py install for scipy ... / Running setup.py install for scipy ... - Running setup.py install for scipy ... \ Running setup.py install for scipy ... error ``` --- pip/req/req_install.py | 19 +++--- pip/utils/__init__.py | 43 +++++++------ pip/utils/ui.py | 142 ++++++++++++++++++++++++++++++++++++++++- pip/wheel.py | 34 +++++----- 4 files changed, 193 insertions(+), 45 deletions(-) diff --git a/pip/req/req_install.py b/pip/req/req_install.py index 4ed58f29c56..708c2d010b9 100644 --- a/pip/req/req_install.py +++ b/pip/req/req_install.py @@ -34,6 +34,7 @@ get_installed_version, canonicalize_name ) from pip.utils.logging import indent_log +from pip.utils.ui import open_spinner from pip.req.req_uninstall import UninstallPathSet from pip.vcs import vcs from pip.wheel import move_wheel_files, Wheel @@ -828,7 +829,7 @@ def install(self, install_options, global_options=[], root=None): temp_location = tempfile.mkdtemp('-record', 'pip-') record_filename = os.path.join(temp_location, 'install-record.txt') try: - install_args = [sys.executable] + install_args = [sys.executable, "-u"] install_args.append('-c') install_args.append( "import setuptools, tokenize;__file__=%r;" @@ -854,13 +855,15 @@ def install(self, install_options, global_options=[], root=None): install_args += ['--install-headers', os.path.join(sys.prefix, 'include', 'site', py_ver_str, self.name)] - logger.info('Running setup.py install for %s', self.name) - with indent_log(): - call_subprocess( - install_args + install_options, - cwd=self.source_dir, - show_stdout=False, - ) + msg = 'Running setup.py install for %s' % (self.name,) + with open_spinner(msg) as spinner: + with indent_log(): + call_subprocess( + install_args + install_options, + cwd=self.source_dir, + show_stdout=False, + spinner=spinner, + ) if not os.path.exists(record_filename): logger.debug('Record file %s not found', record_filename) diff --git a/pip/utils/__init__.py b/pip/utils/__init__.py index 30f5e28b458..d1367d5137b 100644 --- a/pip/utils/__init__.py +++ b/pip/utils/__init__.py @@ -3,7 +3,9 @@ import contextlib import errno import locale -import logging +# we have a submodule named 'logging' which would shadow this if we used the +# regular name: +import logging as std_logging import re import os import posixpath @@ -43,8 +45,7 @@ 'get_installed_version'] -logger = logging.getLogger(__name__) - +logger = std_logging.getLogger(__name__) BZ2_EXTENSIONS = ('.tar.bz2', '.tbz') ZIP_EXTENSIONS = ('.zip', '.whl') @@ -642,8 +643,8 @@ def remove_tracebacks(output): def call_subprocess(cmd, show_stdout=True, cwd=None, raise_on_returncode=True, - command_level=logging.DEBUG, command_desc=None, - extra_environ=None): + command_level=std_logging.DEBUG, command_desc=None, + extra_environ=None, spinner=None): if command_desc is None: cmd_parts = [] for part in cmd: @@ -651,17 +652,13 @@ def call_subprocess(cmd, show_stdout=True, cwd=None, part = '"%s"' % part.replace('"', '\\"') cmd_parts.append(part) command_desc = ' '.join(cmd_parts) - if show_stdout: - stdout = None - else: - stdout = subprocess.PIPE logger.log(command_level, "Running command %s", command_desc) env = os.environ.copy() if extra_environ: env.update(extra_environ) try: proc = subprocess.Popen( - cmd, stderr=subprocess.STDOUT, stdin=None, stdout=stdout, + cmd, stderr=subprocess.STDOUT, stdin=None, stdout=subprocess.PIPE, cwd=cwd, env=env) except Exception as exc: logger.critical( @@ -669,18 +666,22 @@ def call_subprocess(cmd, show_stdout=True, cwd=None, ) raise all_output = [] - if stdout is not None: - while True: - line = console_to_str(proc.stdout.readline()) - if not line: - break - line = line.rstrip() - all_output.append(line + '\n') + while True: + line = console_to_str(proc.stdout.readline()) + if not line: + break + line = line.rstrip() + all_output.append(line + '\n') + if show_stdout: logger.debug(line) - if not all_output: - returned_stdout, returned_stderr = proc.communicate() - all_output = [returned_stdout or ''] + if spinner is not None: + spinner.spin() proc.wait() + if spinner is not None: + if proc.returncode: + spinner.finish("error") + else: + spinner.finish("done") if proc.returncode: if raise_on_returncode: if all_output: @@ -699,7 +700,7 @@ def call_subprocess(cmd, show_stdout=True, cwd=None, 'Command "%s" had error code %s in %s', command_desc, proc.returncode, cwd, ) - if stdout is not None: + if not show_stdout: return remove_tracebacks(''.join(all_output)) diff --git a/pip/utils/ui.py b/pip/utils/ui.py index 3db2d835f32..973bc64ec92 100644 --- a/pip/utils/ui.py +++ b/pip/utils/ui.py @@ -4,13 +4,17 @@ import itertools import sys from signal import signal, SIGINT, default_int_handler +import time +import contextlib +import logging from pip.compat import WINDOWS from pip.utils import format_size from pip.utils.logging import get_indentation from pip._vendor import six from pip._vendor.progress.bar import Bar, IncrementalBar -from pip._vendor.progress.helpers import WritelnMixin +from pip._vendor.progress.helpers import (WritelnMixin, + HIDE_CURSOR, SHOW_CURSOR) from pip._vendor.progress.spinner import Spinner try: @@ -20,6 +24,8 @@ except Exception: colorama = None +logger = logging.getLogger(__name__) + def _select_progress_class(preferred, fallback): encoding = getattr(preferred.file, "encoding", None) @@ -197,3 +203,137 @@ def update(self): ]) self.writeln(line) + + +################################################################ +# Generic "something is happening" spinners +# +# We don't even try using progress.spinner.Spinner here because it's actually +# simpler to reimplement from scratch than to coerce their code into doing +# what we need. +################################################################ + +@contextlib.contextmanager +def hidden_cursor(file): + # The Windows terminal does not support the hide/show cursor ANSI codes, + # even via colorama. So don't even try. + if WINDOWS: + yield + else: + file.write(HIDE_CURSOR) + try: + yield + finally: + file.write(SHOW_CURSOR) + + +class RateLimiter(object): + def __init__(self, min_update_interval_seconds): + self._min_update_interval_seconds = min_update_interval_seconds + self._last_update = 0 + + def ready(self): + now = time.time() + delta = now - self._last_update + return delta >= self._min_update_interval_seconds + + def reset(self): + self._last_update = time.time() + + +class InteractiveSpinner(object): + def __init__(self, message, file=None, spin_chars="-\\|/", + # Empirically, 8 updates/second looks nice + min_update_interval_seconds=0.125): + self._message = message + if file is None: + file = sys.stdout + self._file = file + self._rate_limiter = RateLimiter(min_update_interval_seconds) + self._finished = False + + self._spin_cycle = itertools.cycle(spin_chars) + + self._file.write(" " * get_indentation() + self._message + " ... ") + self._width = 0 + + def _write(self, status): + assert not self._finished + # Erase what we wrote before by backspacing to the beginning, writing + # spaces to overwrite the old text, and then backspacing again + backup = "\b" * self._width + self._file.write(backup + " " * self._width + backup) + # Now we have a blank slate to add our status + self._file.write(status) + self._width = len(status) + self._file.flush() + self._rate_limiter.reset() + + def spin(self): + if self._finished: + return + if not self._rate_limiter.ready(): + return + self._write(next(self._spin_cycle)) + + def finish(self, final_status): + if self._finished: + return + self._write(final_status) + self._file.write("\n") + self._file.flush() + self._finished = True + + +# Used for dumb terminals, non-interactive installs (no tty), etc. +# We still print updates occasionally (once every 60 seconds by default) to +# act as a keep-alive for systems like Travis-CI that take lack-of-output as +# an indication that a task has frozen. +class NonInteractiveSpinner(object): + def __init__(self, message, min_update_interval_seconds=60): + self._message = message + self._finished = False + self._rate_limiter = RateLimiter(min_update_interval_seconds) + self._update("started") + + def _update(self, status): + assert not self._finished + self._rate_limiter.reset() + logger.info("%s: %s", self._message, status) + + def spin(self): + if self._finished: + return + if not self._rate_limiter.ready(): + return + self._update("still running...") + + def finish(self, final_status): + if self._finished: + return + self._update("finished with status '%s'" % (final_status,)) + self._finished = True + + +@contextlib.contextmanager +def open_spinner(message): + # Interactive spinner goes directly to sys.stdout rather than being routed + # through the logging system, but it acts like it has level INFO, + # i.e. it's only displayed if we're at level INFO or better. + # Non-interactive spinner goes through the logging system, so it is always + # in sync with logging configuration. + if sys.stdout.isatty() and logger.getEffectiveLevel() <= logging.INFO: + spinner = InteractiveSpinner(message) + else: + spinner = NonInteractiveSpinner(message) + try: + with hidden_cursor(sys.stdout): + yield spinner + except KeyboardInterrupt: + spinner.finish("canceled") + raise + except Exception: + spinner.finish("error") + raise + else: + spinner.finish("done") diff --git a/pip/wheel.py b/pip/wheel.py index d7ead94ab9a..cc7f6d8cbe9 100644 --- a/pip/wheel.py +++ b/pip/wheel.py @@ -32,6 +32,7 @@ from pip import pep425tags from pip.utils import ( call_subprocess, ensure_dir, captured_stdout, rmtree, canonicalize_name) +from pip.utils.ui import open_spinner from pip.utils.logging import indent_log from pip._vendor.distlib.scripts import ScriptMaker from pip._vendor import pkg_resources @@ -686,7 +687,7 @@ def _build_one(self, req, output_dir, python_tag=None): def _base_setup_args(self, req): return [ - sys.executable, '-c', + sys.executable, "-u", '-c', "import setuptools;__file__=%r;" "exec(compile(open(__file__).read().replace('\\r\\n', '\\n'), " "__file__, 'exec'))" % req.setup_py @@ -695,20 +696,23 @@ def _base_setup_args(self, req): def __build_one(self, req, tempd, python_tag=None): base_args = self._base_setup_args(req) - logger.info('Running setup.py bdist_wheel for %s', req.name) - logger.debug('Destination directory: %s', tempd) - wheel_args = base_args + ['bdist_wheel', '-d', tempd] \ - + self.build_options - - if python_tag is not None: - wheel_args += ["--python-tag", python_tag] - - try: - call_subprocess(wheel_args, cwd=req.source_dir, show_stdout=False) - return True - except: - logger.error('Failed building wheel for %s', req.name) - return False + spin_message = 'Running setup.py bdist_wheel for %s' % (req.name,) + with open_spinner(spin_message) as spinner: + logger.debug('Destination directory: %s', tempd) + wheel_args = base_args + ['bdist_wheel', '-d', tempd] \ + + self.build_options + + if python_tag is not None: + wheel_args += ["--python-tag", python_tag] + + try: + call_subprocess(wheel_args, cwd=req.source_dir, + show_stdout=False, spinner=spinner) + return True + except: + spinner.finish("error") + logger.error('Failed building wheel for %s', req.name) + return False def _clean_one(self, req): base_args = self._base_setup_args(req)