pmxbot IRC Log Viewer

[12:49:39] <mitsuhiko> dstufft: remember that pip install editable not printing stuff?

[12:49:49] <mitsuhiko> it's consistently doing that for me again after my week of holidays -.-

[12:49:53] <dstufft> mitsuhiko: yea

[12:49:55] <dstufft> ha

[12:49:56] <mitsuhiko> i did not change anything

[12:50:10] <dstufft> obviously it's telling you to go back on vacation

[12:50:22] <mitsuhiko> ooooh

[12:50:26] <mitsuhiko> hold on

[12:51:40] <mitsuhiko> i wonder if for some reason i am running into this: https://github.com/pypa/pip/issues/3486

[12:53:01] <mitsuhiko> dstufft: fwiw, i have never seen the spinner

[12:53:33] <mitsuhiko> same on new venv. 8.1.2 on 2.7.10

[12:53:57] <mitsuhiko> oddly enough i swear i have seen this work before a week ago

[12:57:10] <dstufft> mitsuhiko: that's odd...

[12:57:16] <dstufft> our UI stuff needs a bit of work in general :/

[12:57:23] <dstufft> it's a bunch of hacked together nonsense

[12:57:27] <mitsuhiko> so i'm 100% sure this is a regression of some sorts in some version of pip

[12:57:47] <mitsuhiko> but i have seen it work and not work in the same version of pip

[12:58:00] <mitsuhiko> so surely there must be something else that affects it

[12:58:17] <dstufft> mitsuhiko: we do some logic based on isatty() on sys.stdout

[13:00:00] <mitsuhiko> do you know where the actual printing is taking place that call_subprocess uses?

[13:00:06] <mitsuhiko> and how it interacts with the spinner

[13:00:47] <mitsuhiko> i'm starting to wonder if the logger somehow misconfigures

[13:00:54] <mitsuhiko> in case the output comes from the logger.debug(line)

[13:00:57] <dstufft> umm

[13:02:33] <dstufft> I know that the spinner stuff is inside of pip/utils/ui.py, and I think that all of the output is handled by call_subprocess via logging, the actual print() inside the logging system is in pip/utils/logging.py

[13:03:08] <dstufft> but it's just a StreamHandler subclass that adds color

[13:03:43] <dstufft> logging is configured at https://github.com/pypa/pip/blob/master/pip/basecommand.py#L126-L187

[13:04:06] <mitsuhiko> dstufft: effectiveLevel is 30

[13:04:07] <mitsuhiko> which is WARNING

[13:04:24] <dstufft> are you using -q?

[13:04:44] <mitsuhiko> --verbose

[13:04:47] <dstufft> we default to INFO... or we should be

[13:05:04] <dstufft> and --verbose should be moving it to DEBUG

[13:05:23] <dstufft> https://github.com/pypa/pip/blob/master/pip/basecommand.py#L108-L118

[13:06:37] <mitsuhiko> actually. you are right

[13:06:39] <mitsuhiko> it's 10

[13:06:43] <mitsuhiko> which i guess is DEBUG

[13:06:46] <mitsuhiko> i'm printing the wrong logger

[13:07:01] <mitsuhiko> so then why does it not print

[13:07:42] <dstufft> can you pastebin what output you do get?

[13:07:43] <mitsuhiko> hmm. no i'm confused now

[13:07:49] <mitsuhiko> dstufft: of what?

[13:07:53] <mitsuhiko> my prints?

[13:07:57] <mitsuhiko> oh. you mean just the run?

[13:07:59] <dstufft> the pip install run

[13:08:00] <dstufft> yea

[13:08:13] <mitsuhiko> sec

[13:09:49] <mitsuhiko> dstufft: https://gist.github.com/mitsuhiko/84aa70ad3387a4e82ca86891ddaa9263

[13:11:42] <dstufft> mitsuhiko: you might have done this already, but at https://github.com/pypa/pip/blob/master/pip/utils/__init__.py#L692 what does logger.getEffectiveLevel() return? is that the 10 you mentioned above?

[13:12:02] <mitsuhiko> i printed that first and i got 30

[13:12:20] <dstufft> interesting

[13:12:27] <mitsuhiko> but let me double check quickly. i have some local changes now on pip

[13:12:37] <mitsuhiko> i did something and i got 10 as well

[13:12:55] <mitsuhiko> oh. that was different venv

[13:12:58] <mitsuhiko> neat

[13:13:01] <mitsuhiko> so i have one that prints 10 and one that prints 30

[13:13:04] <dstufft> we're checking for that to be <= logging.DEBUG< so if that's returning 30 that would be why it's not showing.

[13:13:15] <mitsuhiko> so what's the difference between the two

[13:14:54] <mitsuhiko> none of this makes any sense

[13:15:14] <mitsuhiko> in particular because neither venv prints ;P

[13:15:46] <dstufft> that it's inconsistent is the weirdest part

[13:15:57] <dstufft> maybe virtualenv broke logging somehow

[13:15:59] <mitsuhiko> so the difference between the venvs is that one is a super old one

[13:16:15] <dstufft> which one is superold, 10 or 30

[13:16:22] <mitsuhiko> the one that is super old returns 30

[13:16:25] <mitsuhiko> the new one returns 10

[13:16:35] <mitsuhiko> but they both have the same version of pip from what i can tell

[13:17:03] <mitsuhiko> i would not be surprised if they don't print for different reasons

[13:17:22] <mitsuhiko> dstufft: oh. they also slightly different print output

[13:17:54] <mitsuhiko> let me try to recreate this entire problem from scratch

[13:17:57] <dstufft> but the new one still doesn't print? Odd.. When you dropped the print() into call_subprocess, did you put it right above or inside the if statement there? e.g. do we know that https://github.com/pypa/pip/blob/master/pip/utils/__init__.py#L692 is getting hit at all?

[13:18:15] <dstufft> yea, if you can give me repro instructions and let me see if I can reproduce that'd be great

[13:18:22] <mitsuhiko> dstufft: i printed before the if

[13:18:26] <mitsuhiko> line 691

[13:18:35] <dstufft> Okay

[13:19:05] <dstufft> so unless we somehow broke basic math, logger.debug should be getting called

[13:19:13] <mitsuhiko> yeah. it is being called

[13:19:30] <mitsuhiko> so my guess is that something fucks up the logging setup

[13:19:57] <mitsuhiko> because when it returns 30 it means that's the default

[13:20:07] <mitsuhiko> or if someone just called basicConfig() or something

[13:24:07] <mitsuhiko> that logger has a level set

[13:24:10] <mitsuhiko> how does that make sense

[13:26:12] <dstufft> mitsuhiko: do you see progress bars?

[13:26:14] <dstufft> when you download

[13:36:18] <mitsuhiko> dstufft: does not seem like

[13:37:21] <mitsuhiko> dstufft: i'm going to look at this later. i really need to look for some other bug now :P

[13:37:52] <dstufft> mitsuhiko: no problem :]

[13:38:27] <dstufft> mitsuhiko: btw, on a tangently related thing, click doesn't have anything to handle verbosity in like click.echo or anything does it? If so is there any desire to add that?

[13:38:40] <mitsuhiko> i would be open to that yeah

[13:39:20] <mitsuhiko> dstufft: fwiw, i'm avoiding the problem by downgrading pip for now

[13:39:21] <mitsuhiko> prints

[13:39:24] <mitsuhiko> going to deal with that later

[13:43:17] <dstufft> mitsuhiko: cool, thanks. Think I might poke at adding that to click then, I think that and us figuring out a good pattern for env vars (I think click's built in solution will work here) and config files are the main blockers (besides time) to moving pip to click

[13:43:33] <mitsuhiko> time :D

[13:43:39] <mitsuhiko> when you find a store that sells it, i'm interested

Log file Viewer

Help | Karma | Search:

#pypa logs for Monday the 19th of September, 2016