pyinvoke / invoke

Pythonic task management & command execution.
http://pyinvoke.org
BSD 2-Clause "Simplified" License
4.41k stars 370 forks source link

Invoke==0.12 waits for keypress and gets Broken Pipe when invoking another invoke command through run() #308

Closed tuukkamustonen closed 8 years ago

tuukkamustonen commented 8 years ago

On linux, python 2.7 and invoke==0.12:

from invoke.collection import Collection
from invoke.tasks import ctask

@ctask
def sub(ctx):
    ctx.run('inv hello')

@ctask
def hello(ctx):
    ctx.run('echo hello')

ns = Collection(sub, hello)

Works:

$ inv hello
hello

Fails:

$ inv sub
hello
<stops to wait for a keypress here...>
Traceback (most recent call last):
  File "/home/musttu/.virtualenvs/pyinv/bin/inv", line 11, in <module>
    sys.exit(program.run())
  File "/home/user/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/program.py", line 270, in run
    self.execute()
  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/program.py", line 379, in execute
    executor.execute(*self.tasks)
  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/executor.py", line 114, in execute
    result = call.task(*args, **call.kwargs)
  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/tasks.py", line 113, in __call__
    result = self.body(*args, **kwargs)
  File "/home/musttu/Temp/tasks.py", line 12, in hello
    ctx.run('echo hello')
  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/context.py", line 53, in run
    return runner_class(context=self).run(command, **kwargs)
  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/runners.py", line 232, in run
    raise ThreadException(exceptions)
invoke.exceptions.ThreadException: 
Saw 1 exceptions within threads (OSError):

Thread args: {'kwargs': {'input_': <open file '<stdin>', mode 'r' at 0x7fee83ac00c0>},
 'target': <bound method Local.handle_stdin of <invoke.runners.Local object at 0x7fee81e7d390>>}

Traceback (most recent call last):

  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/runners.py", line 804, in run
    super(_IOThread, self).run()

  File "/usr/lib/python2.7/threading.py", line 763, in run
    self.__target(*self.__args, **self.__kwargs)

  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/runners.py", line 433, in handle_stdin
    self.write_stdin(self.encode(data))

  File "/home/musttu/.virtualenvs/pyinv/local/lib/python2.7/site-packages/invoke/runners.py", line 653, in write_stdin
    return os.write(fd, data)

OSError: [Errno 32] Broken pipe

In 0.11.1 it works just ok.

The use case: While this example doesn't make much sense, in the real world, I'm invoking another invoke commands in sub-directories from a "master" tasks.py.

presidento commented 8 years ago

It is the same in Win64 with Python 3.4, except I got the exception using inv hello, and inv sub cannot be killed with Ctrl+C.

C:\Users\user\temp\pyinvoke test>inv hello
hello
Traceback (most recent call last):
  File "c:\programs\python34\lib\runpy.py", line 170, in _run_module_as_main
    "__main__", mod_spec)
  File "c:\programs\python34\lib\runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "C:\Programs\Python34\Scripts\inv.exe\__main__.py", line 9, in <module>
  File "c:\programs\python34\lib\site-packages\invoke\program.py", line 270, in run
    self.execute()
  File "c:\programs\python34\lib\site-packages\invoke\program.py", line 379, in execute
    executor.execute(*self.tasks)
  File "c:\programs\python34\lib\site-packages\invoke\executor.py", line 114, in execute
    result = call.task(*args, **call.kwargs)
  File "c:\programs\python34\lib\site-packages\invoke\tasks.py", line 113, in __call__
    result = self.body(*args, **kwargs)
  File "C:\Users\user\temp\pyinvoke test\tasks.py", line 10, in hello
    ctx.run('echo hello', shell=True)
  File "c:\programs\python34\lib\site-packages\invoke\context.py", line 53, in run
    return runner_class(context=self).run(command, **kwargs)
  File "c:\programs\python34\lib\site-packages\invoke\runners.py", line 232, in run
    raise ThreadException(exceptions)
invoke.exceptions.ThreadException:
Saw 1 exceptions within threads (OSError):

Thread args: {'kwargs': {'input_': <_io.TextIOWrapper name='<stdin>' mode='r' encoding='cp852'>},
 'target': <bound method Local.handle_stdin of <invoke.runners.Local object at 0x02EF6230>>}

Traceback (most recent call last):

  File "c:\programs\python34\lib\site-packages\invoke\runners.py", line 804, in run
    super(_IOThread, self).run()

  File "c:\programs\python34\lib\threading.py", line 868, in run
    self._target(*self._args, **self._kwargs)

  File "c:\programs\python34\lib\site-packages\invoke\runners.py", line 411, in handle_stdin
    reads, _, _ = select.select([input_], [], [], 0.0)

OSError: [WinError 10093] Either the application has not called WSAStartup, or WSAStartup failed
tuukkamustonen commented 8 years ago

I can kill inv sub with Ctrl+C but if I do that, I get into situation reported in #303.

bitprophet commented 8 years ago

Thanks for the reports! Confirm I can reproduce locally.

On poking, noted that the ThreadError/OSError is in the "inner" invoke process (hello, not sub).

Also noted that the behavior is improved if sub uses run(pty=True); or, unsurprisingly, if both do (can't just put it on hello only though - the inner Invoke will notice the outer isn't a pty and fallback to non-pty execution, as expected).

Handing in_stream=StringIO("") to sub only changes things insofar as sending the real-stdin newline now makes no difference and one is forced to Ctrl-C.

So far I'm assuming there's a race condition or other stupidity going on wrt the input mirror loop (which loops until it receives the signal from another thread that the subprocess has exited). Why this is only triggered by nesting is unclear offhand. Will dig.

bitprophet commented 8 years ago

Also linking this explicitly to #289 since it came out of that feature.

bitprophet commented 8 years ago

Right - it's because Invoke doesn't appear to be a terminal when not in pty mode (because...it's not), and Invoke checks its own stdin for terminal-ness when deciding how to 'wait' on stdin during the stdin read loop: https://github.com/pyinvoke/invoke/blob/7fe2750cd1863c15c3cc92c390dee479dce96534/invoke/runners.py#L413-L447

When a real pty is present (again, this is the case if one uses pty=True in the outer invocation) the "is stdin ready for reading?" function at the top of said loop will never block: it uses select (or Windows equiv), returning False immediately, forever; the loop is thus "hot" (except it doesn't actually chew CPU due to a sleep call :smile_cat:).

In the case under test, where there is no intended stdin data, this means everything lines up well: that loop runs often, eventually the "is the subprocess done?" test triggers, the loop exits, everything closes up shop, we're done.

In the error case, when the input stream doesn't appear to be a terminal (via our custom isatty function) ready_for_reading() always returns True on the presumption that the stream is an in-process Python object or similar finite-length file-like object that can be read(1) from.

So we end up sitting in read_byte, where input_ is an actually-kinda-real sys.stdin, until a byte appears in the stream (this is where 'hitting a key' enters the picture). But at this point in time, the echo subprocess has already exited, thus the OSError on broken pipe when the inner Invoke tries mirroring this read byte into it.


tl;dr: we need at least one of the following:

To be continued...

bitprophet commented 8 years ago

Examining the state of my local setup, I found that while sys.stdin.isatty is False, sys.stdin.fileno is 0. Right now, our isatty test prefers .isatty and completely disregards .fileno if .isatty is callable. However, the case under consideration is exactly the kind of valid setup the code disregards.

It should be the same as some other non-Invoke program piped as stdin to Invoke, which is another case I think we have bug reports for (from earlier) as well. Sure enough, echo 'lolnope' | inv hello yields the exact same set of errors.

So our fixation on "tty-ness" for purposes of how to read from stdin is misguided and needs fixing.

Offhand I am thinking making it "either-or" should suffice (says it's a tty? cool! says it's not a tty, but has a fileno? also cool!) but I need to revisit the reasons why we made it the way it is now (I recall other edge/corner cases being involved).

May also involve splitting the method up a bit - some cases we really do care if it's a TTY, IIRC.

EDIT: yea, here's all calls to utils.isatty at present:


What I need to do:

bitprophet commented 8 years ago

Minor update, I read isatty slightly too fast, the fallback test isn't "does it have a real fileno?" but "does it have a real fileno and is that fileno a tty according to os.isatty?". Which is of course, still False in this particular scenario (both cases).

Also, FTR, the reason it's always false here, but fileno itself is "okay", is because we're just inheriting file handles all the way down; so sys.stdin.fileno() is still 0, like "normal" ("normal" being "a Python process with nothing else in the way of standard input"). But it's not a TTY because either the pipe, or Invoke, is in the way, depending. (N.B. there's now one test for each situation in the integration suite.)

This is definitely hedging me further towards "we need to separate the questions of TTY-ness and select-ability", which I think will solve this pretty well.

bitprophet commented 8 years ago

So yea, re: previous comment, updating isatty to be either-or doesn't help any, as the os.isatty test around the stream's fileno() still fails. Definitely do need separate functions. Working on that now.

bitprophet commented 8 years ago

Dug a little deeper into our use of isatty and friends:

Need to doublecheck to make sure I'm not missing anything, but so far, it does feel like the majority of these actually just care about fileno not isatty - need to check git history too because I'm pretty sure isatty() used to care more about fileno so if so, I wonder why things changed - suspect Windows related?

bitprophet commented 8 years ago

Doublechecked, everything should be listed above now.

Re: git history, we did previously rely mostly on fileno (though this was prior to implementing the stdin mirroring so was mostly used for the Local pty stuff I think), then in 57f7f42ae58bdee383144ebdf41bb549738002d4 it got changed to prefer isatty (and then later in 61feb225fee96799153a36d1a8914cba67e5d0fd we expanded to the current setup of "isatty, then fileno").

I still think that this back & forth is due to the two different questions involved re: Local pty execution jazz vs the concerns about reading from stdin, so I'm gonna steam ahead with that and hope anything it breaks bubbles up quickly.

bitprophet commented 8 years ago

Poked a bit re: above:

bitprophet commented 8 years ago

Grump, went ahead and tried flipping everything back to fileno-only testing, but I obviously didn't test enough. Even though we have useful fileno on sys.stdin in a nested-Invoke situation, character_buffered's call to termios.tcgetattr gets upset and throws Inappropriate ioctl for device.

So we probably do still need a mixture of isatty and fileno checks...testing. EDIT: yup, if we update character_buffered to test isatty but leave everything else testing fileno, the test case here (re: inv sub) now works for me.

bitprophet commented 8 years ago

Test suites now finding some more quirks I hadn't run into yet, firstly: an integration test that incidentally calls invoke-from-invoke (testing --help output) yields an IOError of Inappropriate ioctl for device in pty_size's use of fcntl.ioctl.

bitprophet commented 8 years ago

Have everything passing now except for the echo 'lol' | invoke sometask integration test (this wasn't reported initially but it's a legit use case) which seems to be encountering a race condition - the waiting for the subprocess (which is simply echo meh) finishes before the stdin mirroring completes.

In most real-world x | y cases this isn't an issue; AFAIK the shell simply discards anything in the pipe if the receiving end closes "early". In our case, what's really happening is more akin to x | invoke | y, and so it's up to us to notice this problem & deal accordingly.

Presumably we simply need to capture this OSError and just close up shop; now that we've solved the similar issue of "don't try to get at least one read() from a stream with nothing in it", this situation should be the only cause of broken-pipe OSErrors. Hopefully.

bitprophet commented 8 years ago

This makes me wonder if for "best behavior" we should disable the stdin mirroring IO sleep when stdin fails isatty testing. E.g. cat /usr/share/dict/web2 | echo wut (that dict file is 2.4MB of text) takes 0.005s to run on my i7-based Macbook Air, but obviously significantly longer when polling stdin 1 byte at a time with a 0.01s sleep.

I also ran into the part where we always echo stdin when using_pty is false; that functionality also needs to check whether the input is running in a pty, because otherwise it tries to write to our stdout even though we're running it via a pipe - that's incorrect.

Terminals are great fun.

bitprophet commented 8 years ago

Tackling the echoing/mirroring (I really need to get better at consistent vocabulary with this shit) first:

bitprophet commented 8 years ago

Hrm. So...we can sorta detect a pipe vs nested situation by testing both stdout and stdin:

But that doesn't really help, because the point of this is to echo a real user's typing back to them.

Given how much dumb time I've sunk into this, going with option 3 from previous comment - add an option to control the echoing, have it default to "only if stdin passes isatty and subprocess isn't running in a pty".

bitprophet commented 8 years ago

While it didn't take the whole 6 hours since last note, it still took longer than it should have to finished getting that working (mostly due to testing related concerns). I'm bad at computers, folks :(

On the plus side we now have yet another run kwarg/config option controlling stdin echoing.

Re: the other side note of disabling IO sleep, I am punting on that because of aforementioned difficulty in telling apart a pipe from a nested session (& also just time).

Flake8 and Python 3 are satisfied locally; time to see if my integration tests for the greater issue here, works on Travis or not. I bet they don't. If they don't I am probably just going to tell them to skip on Travis, again because JFC I need to wrap this up.

bitprophet commented 8 years ago

Incredibly, I was wrong, the tests seem to pass on Travis. Suppose maybe it's a false positive, but meh.

Uh...I think this and all its attendant sub-problems are now Fixed Enough, writing a changelog entry and merging. Sorry for the chatter @tuukkamustonen and @presidento !

tuukkamustonen commented 8 years ago

@bitprophet That's some incredible work there. The way you summarize the thought-process into tickets for others to follow and collaborate is exceptional and I'm just happy about the lenghty "chatter". That being said, you lost me halfway through (if not earlier, this stuff is way out of my knowledge) but I do really appreciate the effort you're putting into the project(s)!

presidento commented 8 years ago

I agree with @tuukkamustonen, thank @bitprophet for the summaries. I have read it as was posted.

bitprophet commented 8 years ago

:heart: