Teach `pip` to play along with `head` unix-command #5721

ankostis · 2018-08-21T14:41:00Z

Fix #4170: Override ColorizedStreamHandler.flush() to ignore BrokenPipeError exceptions.

Note, it would be hard to make a test-case for it, no?

pfmoore · 2018-08-21T14:53:31Z

src/pip/_internal/utils/logging.py

+        """Ignore `BrokenPipeErrors` on `flush()`."""
+        try:
+            self.flush()
+        except BrokenPipeError:


BrokenPipeError wasn't defined in Python 2, so you'll need something different for that case

pfmoore · 2018-08-21T14:53:42Z

Note, it would be hard to make a test-case for it, no?

Well, you said that pip list | head fails with an error and it shouldn't. That sounds easy enough to write a test for 😄

pradyunsg · 2018-08-21T15:04:15Z

src/pip/_internal/utils/logging.py

+    def flush(self):
+        """Ignore `BrokenPipeErrors` on `flush()`."""
+        try:
+            self.flush()


This should be super(..., self).flush().

pradyunsg · 2018-08-21T15:05:32Z

news/4170.bugfix

@@ -0,0 +1,2 @@
+Teach pip's logging-handler to stay calm on `BrokenPipeError`, probably *stderr* redirected to :command:`head`.


This should probably be something like:

Avoid printing a Traceback when a broken pipe is encountered in stderr (like when piping through `head` on Unix)

ankostis · 2018-08-21T15:08:23Z

Any idea where to attache the TC?

pradyunsg · 2018-08-21T15:16:08Z

@ankostis What's TC?

ankostis · 2018-08-21T15:28:15Z

What's TC?

The one suggested by @pfmoore.
Which file should i put it?

tests/scripts/test_all_pip.py
tests/unit/test_base_command:Test_base_command_logging

pfmoore · 2018-08-21T15:30:30Z

What's TC?

I'm guessing "test case". I don't really have any good feel for where would be the best place in the test suite for something like this, so I can't really suggest a location, I'm afraid.

ankostis · 2018-08-21T15:35:48Z

The most relevant TC is tests/functional/test_no_color.py bc it runs pip as external command, and checks the color-logging-handler. But the name is a bit irrelevant.

I will put it here, and someone may rename this test-module, if you don't have any objections.

pradyunsg · 2018-08-21T15:44:58Z

You can add that test there and rename that file to test_logging.py.

ankostis · 2018-08-21T16:19:18Z

Without the TC yet, travis is ok.

Note that pip list, suggested above, writes to STDOUT, whuch is not handled by logging, and not addressed by this PR - i would prefer not to extend this PR to that.

pradyunsg · 2018-08-21T16:22:59Z

Extend it to renaming the file? No worries. I'll be okay with doing it myself in a follow up.

ankostis · 2018-08-21T16:24:59Z

No, ididn' mean that., i can rename it the test-case module.

I guess pip has 2 "pipelines" for output, 1) logging, 2) pure writes to stdout/stderr, correct.
This PR deals with (2) logging only.

pradyunsg · 2018-08-21T18:36:23Z

src/pip/_vendor/colorama/ansitowin32.py

@@ -136,12 +137,25 @@ def get_win32_calls(self):
            }
        return dict()

+    def _flush(self):


You've modified a vendored library - colorama. What's the reason you had to do this?

pip actively avoids patching it's vendored libraries in favour of making changes upstream and absorbing those changes when a new release is made.

As explained it also in conversation, patching logger is not enough.

In windows, as soon as you patch it and try to redirect to head, that this the next point where it fails on broken-pipe.
And not only it simply fails, but if you ignore also at that point pipe-errors, you then get a mysterious EINVAL OSError:

File "pip\_vendor\colorama\ansitowin32.py", line 143, in _flush self.wrapped.flush() OSError: [Errno 22] Invalid argument

If you ignore also that, then it works.

Now i'm also surprised that Colorama has not fixed it, and i search a bit and did not fimnd anything related reported.
Certainly if it is fixable, it should be fixed there.

bc on Windows it breaks with OSError(errno.EINVAL) after pip has broken. + Fix a bit the TC according to PY2 behavior.

ankostis · 2018-08-22T16:01:52Z

Ok another day, another look....i abandoned pip list | head and mimicked its behavior with Popen(), then closing its stdout prematurely and counting the lines printed in stderr. It is there that the standard logging subsystem dumps stack-traces of exceptions collected while emitting log-records.

2 new TCs have been introduced in the renamed test_loggin.py file, committed before the fix-commits of this PR, to compare behavior before and after:

test_broken_pipe_output() TC which does a "sanity" output check whether pip freeze breaks politely on broken-pipes. The freeze command is special, in that it writes stdout in a loop - all the rest commands are using logging system to print their results (relevant to next TC). Therefore:
- even before the fix (7f4ec24, add TCs), a broken-pipe-error breaks immediately the command, and the TC passes (travis#419216427).
- This behavior remains unaffected after the fixes.
The test_broken_pipe_logger() TC checks politeness of download cmd (many logs) against broken-pipes.
- Before the fix, it is impolite, and emits ~5-6 log lines per each of-statement (~5k lines).
- After the 1st fix-commit(28beeeb , patch logHandler), it works on Linux, but keeps failing on Windows, due to colorama (appveyor#1.0.3221), as discussed earlier.
- After the 2nd (b84dfe7, patch colorama), it stops emitting more logs, yet the command continues to run until the end ( travis#9449).

PR graduated from [WIP] (but still not decided whether to push upstream fix to colorama).

ankostis · 2018-08-22T16:07:11Z

Note: At the moment have pushed one commit back in time from b84dfe7, and wait for Appveyor to validate it.

pfmoore · 2018-08-22T16:13:19Z

tests/functional/test_logging.py

+        "Expected no color in output"
+
+
+def _run_and_brake_stdout(cmd, read_nchars=1, check=False, **popen_kw):


Nit: Spelling is "break" not "brake".

pfmoore · 2018-08-22T16:13:30Z

tests/functional/test_logging.py

+
+def _run_and_brake_stdout(cmd, read_nchars=1, check=False, **popen_kw):
+    """
+    Launch Popen, brake stdout, ignore returncode and return stderr.


pfmoore · 2018-08-22T16:23:21Z

tests/functional/test_logging.py

+    if check:
+        assert not proc.returncode, (proc.returncode, cmd, err)
+
+    return err


This actually seems way too complicated. I'd be concerned that there are bugs in the test code here. Not that I can see any, just that it's not obvious what it's testing.

To reiterate what I said originally, what's wrong with something as simple as

text = subprocess.check_output('pip --help | head`, stderr=subprocess.STDOUT, shell=True) assert 'Broken pipe' in text

You may have to only run the test on Unix, as Windows doesn't have a head command by default, but I wouldn't be too worried about that. To be fair though, I'm not actually convinced that the broken pipe error is bad enough to be worth worrying about in the first place...

Windows doesn't have a head command ... but I wouldn't be too worried about that

No no, there's MSYS2 (posix) on appveyor (among others), head wouldn't be a problem.
Testing on Windows is important. You see, i discovered the colorama problem, captured by the TCs, (appveyor#1.0.3221), and fixed by the 2nd fix-commit.

what's wrong with something as simple as subprocess.check_output('pip --help | head' ...

I've pushed the simplified variant you suggested, and the strange errors started.
Additionally, in Windows i'm infested by #3383 and cannot test cleanly locally, and going back and forth to virtualbox is tiring...
I remember these 2 days fighting them, my apologies, i don't remember all the nuances that made me turn around.
Any ideas?

BTW: pip --help is not printing through logger, which this PR is about, but through argparse (no?) - we need a command with many separate log-statements, like download, or install. Is there any other?

I'm not actually convinced that the broken pipe error is bad enough

I scratched my itch when i was fighting package/version resolution problems, and used head to view just the few first lines of the logs, but still, a torrent of 5000+ lines scrolled down my console too quickly for Ctrl+C to work - i don't know how to say it, but a tool not going along with head feels rude to me (hope it's not too impolite to say it).

a tool not going along with head feels rude to me (hope it's not too impolite to say it).

Not at all, and if it caused you a problem and you were considerate enough to spend time fixing it for us, I'm very grateful. All I was trying to say was that I'm not a good judge of how much effort it's worth spending on this, as it doesn't bother me that much.

I understand about the annoyances testing. I don't know of a good answer - I do basically what you do, I push a WIP change and let the CI run the tests. What you can do, once you have a specific test that you want to work on, is run that test alone using tox -e py36 -- tests\functional\test_logging.py -k test_broken_pipe_logger specifying the file and test name. That's usually fast enough to be workable.

I'll try to find some time tomorrow and look through the bugs you're hitting, and see if I can shed any light on them.

ankostis · 2018-08-23T11:48:38Z

Created a new PR #5729 with the pip | head test-case, to keep this pure-python variant that is working ok, clean.

cjerdonek · 2019-01-21T21:51:21Z

Closing this for the same reason mentioned in PR #5729 (superseded by PR #5907, which was recently merged): #5729 (comment) Thanks for your contributions, @ankostis.

lock · 2019-05-30T17:48:19Z

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.

ankostis changed the title ~~Teach log-handler to stay calm on broken-pipes eg. pip | head~~ WIP: Teach log-handler to stay calm on broken-pipes eg. pip | head Aug 21, 2018

pfmoore reviewed Aug 21, 2018

View reviewed changes

pradyunsg added state: needs discussion This needs some more discussion T: bugfix labels Aug 21, 2018

pradyunsg changed the title ~~WIP: Teach log-handler to stay calm on broken-pipes eg. pip | head~~ [WIP] Teach log-handler to stay calm on broken-pipes eg. pip | head Aug 21, 2018

ankostis force-pushed the fix_logging_broken_pipes branch from 8afa21a to efc5c51 Compare August 21, 2018 15:05

pradyunsg reviewed Aug 21, 2018

View reviewed changes

ankostis force-pushed the fix_logging_broken_pipes branch from 299c751 to 64dcb57 Compare August 21, 2018 15:19

ankostis force-pushed the fix_logging_broken_pipes branch from 64dcb57 to 025f3cc Compare August 21, 2018 18:15

ankostis force-pushed the fix_logging_broken_pipes branch from 025f3cc to 1be0063 Compare August 21, 2018 18:20

pradyunsg reviewed Aug 21, 2018

View reviewed changes

ankostis force-pushed the fix_logging_broken_pipes branch from aa65d5d to 967f2d0 Compare August 21, 2018 18:57

ankostis force-pushed the fix_logging_broken_pipes branch from 967f2d0 to 2804481 Compare August 21, 2018 18:59

ankostis force-pushed the fix_logging_broken_pipes branch from acc2010 to 3a5c131 Compare August 22, 2018 14:20

ankostis force-pushed the fix_logging_broken_pipes branch from 3a5c131 to 74dcba3 Compare August 22, 2018 14:37

ankostis force-pushed the fix_logging_broken_pipes branch from 74dcba3 to bd530f7 Compare August 22, 2018 14:42

[WIP] enh: test-cases for pypa#5721 for logging not to fail when piped

7f4ec24

ankostis force-pushed the fix_logging_broken_pipes branch from bd530f7 to 7f4ec24 Compare August 22, 2018 14:52

fix pypa#4170: log ignores broken-pipes in STDERR when pip | head

28beeeb

ankostis force-pushed the fix_logging_broken_pipes branch 3 times, most recently from c82fdcd to 28beeeb Compare August 22, 2018 15:28

fix: patch also stdout.flush() from colorama for pypa#4170

b84dfe7

bc on Windows it breaks with OSError(errno.EINVAL) after pip has broken. + Fix a bit the TC according to PY2 behavior.

ankostis force-pushed the fix_logging_broken_pipes branch from b84dfe7 to 28beeeb Compare August 22, 2018 16:01

pfmoore requested changes Aug 22, 2018

View reviewed changes

style: "brake" typos func-names and comments

b096426

ankostis force-pushed the fix_logging_broken_pipes branch 3 times, most recently from edc5a84 to b096426 Compare August 23, 2018 11:41

ankostis mentioned this pull request Aug 23, 2018

Fix logging broken pipes2 #5729

Closed

ankostis changed the title ~~[WIP] Teach log-handler to stay calm on broken-pipes eg. pip | head~~ Teach log-handler to stay calm on broken-pipes eg. pip | head Aug 23, 2018

ankostis changed the title ~~Teach log-handler to stay calm on broken-pipes eg. pip | head~~ Teach pip to play along with head unix-command Aug 23, 2018

cjerdonek closed this Jan 21, 2019

lock bot added the auto-locked Outdated issues that have been locked by automation label May 30, 2019

lock bot locked as resolved and limited conversation to collaborators May 30, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Teach `pip` to play along with `head` unix-command #5721

Teach `pip` to play along with `head` unix-command #5721

ankostis commented Aug 21, 2018 •

edited

Loading

pfmoore Aug 21, 2018

pfmoore commented Aug 21, 2018

pradyunsg Aug 21, 2018

pradyunsg Aug 21, 2018 •

edited

Loading

ankostis commented Aug 21, 2018

pradyunsg commented Aug 21, 2018

ankostis commented Aug 21, 2018

pfmoore commented Aug 21, 2018

ankostis commented Aug 21, 2018

pradyunsg commented Aug 21, 2018

ankostis commented Aug 21, 2018

pradyunsg commented Aug 21, 2018

ankostis commented Aug 21, 2018

pradyunsg Aug 21, 2018

ankostis Aug 21, 2018 •

edited

Loading

ankostis commented Aug 22, 2018 •

edited

Loading

ankostis commented Aug 22, 2018

pfmoore Aug 22, 2018

ankostis Aug 22, 2018

pfmoore Aug 22, 2018

ankostis Aug 22, 2018

pfmoore Aug 22, 2018

ankostis Aug 22, 2018 •

edited

Loading

pfmoore Aug 22, 2018

ankostis commented Aug 23, 2018

cjerdonek commented Jan 21, 2019

lock bot commented May 30, 2019

		@@ -0,0 +1,2 @@
		Teach pip's logging-handler to stay calm on `BrokenPipeError`, probably stderr redirected to :command:`head`.

		"Expected no color in output"


		def _run_and_brake_stdout(cmd, read_nchars=1, check=False, **popen_kw):

Teach pip to play along with head unix-command #5721

Teach pip to play along with head unix-command #5721

Conversation

ankostis commented Aug 21, 2018 • edited Loading

Choose a reason for hiding this comment

pfmoore commented Aug 21, 2018

Choose a reason for hiding this comment

pradyunsg Aug 21, 2018 • edited Loading

Choose a reason for hiding this comment

ankostis commented Aug 21, 2018

pradyunsg commented Aug 21, 2018

ankostis commented Aug 21, 2018

pfmoore commented Aug 21, 2018

ankostis commented Aug 21, 2018

pradyunsg commented Aug 21, 2018

ankostis commented Aug 21, 2018

pradyunsg commented Aug 21, 2018

ankostis commented Aug 21, 2018

Choose a reason for hiding this comment

ankostis Aug 21, 2018 • edited Loading

Choose a reason for hiding this comment

ankostis commented Aug 22, 2018 • edited Loading

ankostis commented Aug 22, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ankostis Aug 22, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ankostis commented Aug 23, 2018

cjerdonek commented Jan 21, 2019

lock bot commented May 30, 2019

Teach `pip` to play along with `head` unix-command #5721

Teach `pip` to play along with `head` unix-command #5721

ankostis commented Aug 21, 2018 •

edited

Loading

pradyunsg Aug 21, 2018 •

edited

Loading

ankostis Aug 21, 2018 •

edited

Loading

ankostis commented Aug 22, 2018 •

edited

Loading

ankostis Aug 22, 2018 •

edited

Loading