Display spinner during long setup.py calls

[njsmith]

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.

Here's a proof of concept of an idea discussed here:

#2732 (comment)

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.

Reasons this is only a proof of concept:

• no rate-limiting
• the current UI is unacceptable -- try it and you'll see what I mean,
  but basically it puts the spinner in a weird place and then leaves
  detritus behind.

The underlying reason for both of these is that I find the progress
bar/spinner system totally incomprehensible (you are lost in a maze of
twisty mixins, all different...), and am also uncertain how to integrate
it with the existing messages that go via logger.info... If I knew how
I'd have made it produce output 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.

...but I don't.

[njsmith]

CC @rgommers

[dstufft]

The answer is basically that you can't have the spinner (and any messages included in it) going through the logger. So you have to make it so that the spinner and any associated messages can be omitted without making the UI confusing. One example might be to do something like this (psuedo-ish code):

logger.debug("Executing setup.py bdist_wheel for scipy")
if logger.getEffectiveLevel() <= logging.INFO:
    spinner("Building scipy")

[njsmith]

Okay, that wasn't so bad, actually. I think this is ready for review.

[dstufft]

You have some assertions you're going to need to change.

[dstufft]

It might be reasonable to make the messages a bit more abstract. Instead of something like "Running setup.py bdist_wheel" we could say "Building a Wheel". The exact command being run is still available as a logging message when running with -v so we're not losing the ability to get at the information, but it might be a nicer UI to have a more human message and as a plus side, the messages will be ready for an eventual future where setup.py is no longer required.

[njsmith]

Ready for re-review. Remaining build failures appear to be network flakiness, nothing to do with the patch.

The reason the tests were (genuinely) failing before was that I moved the output of text like Running setup.py install for ... into the spinner, and then it turns out that spinners are suppressed entirely when stdout is not a tty, so in non-interactive situations the message was just getting lost entirely. So that was a genuine bug. I ended up fixing this by rewriting the code for the command-running spinner from scratch. It's much easier to understand and more featureful now that I'm not trying to use the progress library :-). The interaction between the spinner and the logging system is still a bit ugly, and probably at some point the whole output system should get overhauled and replaced with something that combines knowledge of spinners/progress-bars/logging-levels into a unified system, but for now this seems to work pretty well.

I decided not to get ambitious about changing the text of the commands in this patch -- can always do it later :-).

The main remaining issue I noticed is that in pip install scipy, there's a very long pause during the "Collecting" phase, because it turns out that just running egg_info on scipy is rather slow (tens of seconds), and since pip doesn't tell you that it's running egg_info, then you don't get a spinner for it either. I left this as-is for now, but might be something to fix eventually.

[dstufft]

I'm confused why this change is needed. You don't seem to be using the name logging anywhere except for the stdlib logging. There is a pip.utils.logging module, but that shouldn't cause any problems.

[njsmith]

It may not be needed anymore, but it's a good idea in any case. The problem
is that this is utils/init.py, so as soon as someone else imports
utils/logging.py, any global variable that we have named 'logging' will get
clobbered by the import system, because this is utils.logging. In fact
this was happening before, but no one had noticed because 'logging' was
only accessed during initial startup, never during runtime, and the
clobbering happened but not until after the last time it was used. Probably
the real solution is to move all this code into a proper submodule instead
of keeping it in init.py, but one thing at a time...
On Nov 6, 2015 4:58 AM, "Donald Stufft" notifications@github.com wrote:

In pip/utils/init.py
#3224 (comment):

@@ -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

I'm confused why this change is needed. You don't seem to be using the
name logging anywhere except for the stdlib logging. There is a
pip.utils.logging module, but that shouldn't cause any problems.

—
Reply to this email directly or view it on GitHub
https://github.com/pypa/pip/pull/3224/files#r44133422.

[njsmith]

OK, yeah, after a quick skim, it looks like this isn't technically needed anymore. At some point during development the logger.getEffectiveLevel() <= logging.INFO check was happening inside call_subprocess, and erroring out because logging.INFO didn't exist, which confused the heck out of me for a while. So I think this renaming is still a good change, though now technically unrelated to the rest of the PR.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.