search

prompt-toolkit / python-prompt-toolkit

Library for building powerful interactive command line applications in Python
https://python-prompt-toolkit.readthedocs.io/
BSD 3-Clause "New" or "Revised" License
9.25k stars 715 forks source link

patch_stdout sometimes throws exception? #731

Open vlovich opened 5 years ago

vlovich commented 5 years ago

Sometimes I get this exception when I enter input.

Traceback (most recent call last):
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "prompt_toolkit/eventloop/context.py", line 115, in new_func
    return func(*a, **kw)
  File "prompt_toolkit/patch_stdout.py", line 97, in write_and_flush_in_loop
    run_in_terminal(write_and_flush, in_executor=False)
  File "prompt_toolkit/application/run_in_terminal.py", line 41, in run_in_terminal
    return run_coroutine_in_terminal(async_func, render_cli_done=render_cli_done)
  File "prompt_toolkit/application/run_in_terminal.py", line 62, in run_coroutine_in_terminal
    assert app._is_running
AssertionError

My input processing loop looks like this:

    parser = user_input_parser()
    validator = Validator.from_callable(
      lambda _: PROMPT_STATE.enabled, error_message="Terminal not available")
    while True:
      try:
        with patch_stdout(raw=True):
          user_input = await session.prompt(
            lambda: "> " if PROMPT_STATE.enabled else "", async_=True,
            rprompt=lambda: PROMPT_STATE.status, validator=validator,
            validate_while_typing=True)

        if not PROMPT_STATE.enabled:
          continue
      except KeyboardInterrupt:
        return

      parse_input(user_input.strip())

I'm dumping things to the screen via python logging module but AFAIK I don't have any threads going on. Maybe there's a bug where prompt toolkit is launching threads unnecessarily? It seems like there's a few threads doing sleeps in key_processor which seems weird (wouldn't there only be 1?) but not sure if related or expected behaviour. Is it possible I'm doing something very wrong?

MainThread <_MainThread(MainThread, started 140735655584640)>
  File "shell.py", line 1404, in <module>
    sys.exit(main(sys.argv[1:]) or 0)
  File "shell.py", line 1398, in main
    loop.run_until_complete(prompt_task)
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py", line 555, in run_until_complete
    self.run_forever()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py", line 523, in run_forever
    self._run_once()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py", line 1758, in _run_once
    handle._run()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/events.py", line 100, in _run
    self._loop.call_exception_handler(context)
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py", line 1626, in call_exception_handler
    self._exception_handler(self, context)
  File "shell.py", line 1272, in exception_handler
    file=exception_stderr)

Thread-1 <Thread(Thread-1, started daemon 123145533894656)>
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 885, in _bootstrap
    self._bootstrap_inner()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "prompt_toolkit/eventloop/utils.py", line 33, in run
    result = self.target()
  File "prompt_toolkit/key_binding/key_processor.py", line 378, in wait
    time.sleep(timeout)

Thread-2 <Thread(Thread-2, started daemon 123145539149824)>
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 885, in _bootstrap
    self._bootstrap_inner()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "prompt_toolkit/eventloop/utils.py", line 33, in run
    result = self.target()
  File "prompt_toolkit/key_binding/key_processor.py", line 378, in wait
    time.sleep(timeout)

Thread-3 <Thread(Thread-3, started daemon 123145544404992)>
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 885, in _bootstrap
    self._bootstrap_inner()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "prompt_toolkit/eventloop/utils.py", line 33, in run
    result = self.target()
  File "prompt_toolkit/application/application.py", line 562, in <lambda>
    lambda: auto_flush_input(counter), _daemon=True)
  File "prompt_toolkit/application/application.py", line 567, in auto_flush_input
    time.sleep(self.ttimeoutlen)

Thread-4 <Thread(Thread-4, started daemon 123145549660160)>
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 885, in _bootstrap
    self._bootstrap_inner()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "prompt_toolkit/eventloop/utils.py", line 33, in run
    result = self.target()
  File "prompt_toolkit/key_binding/key_processor.py", line 378, in wait
    time.sleep(timeout)

Thread-5 <Thread(Thread-5, started daemon 123145554915328)>
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 885, in _bootstrap
    self._bootstrap_inner()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/opt/homebrew/Cellar/python/3.7.0/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "prompt_toolkit/eventloop/utils.py", line 33, in run
    result = self.target()
  File "prompt_toolkit/application/application.py", line 562, in <lambda>
    lambda: auto_flush_input(counter), _daemon=True)
  File "prompt_toolkit/application/application.py", line 567, in auto_flush_input
    time.sleep(self.ttimeoutlen)
vlovich commented 5 years ago

Oh, the problem only really manifests (or at least easiest to reproduce) if I'm dumping a lot of logs continuously. The logs are generated primarily through here: loop.add_reader(fd, fd_callback) which is monitoring an external pipe for messages to handle.

vlovich commented 5 years ago

Minimum reproducible test case. When running just hold the enter key.

test.txt

jonathanslenders commented 5 years ago

That looks like a bug. Thanks a lot for reporting and creating this minimum test case file. That is super useful! Right now, I'm not yet sure what's going on.

Verequies commented 5 years ago

I have also come across this bug and yeah, only appears when both the logs are being dumped and the prompt is exiting and entering continuously.

https://github.com/prompt-toolkit/python-prompt-toolkit/blob/bc9f4eb3953e0af29f047ce9fd016da90f6443ad/prompt_toolkit/application/run_in_terminal.py#L60-L62

Line 62 is the point where the crash occurs, and I believe the cause is because the prompt is constantly exiting and entering that at a given point it might not be None but also not running.

Had a quick go at fixing this by just modifying line 60 to also check if the app is not running, like below, seems to have solved the issue.

    if app is None or not app._is_running:
        return ensure_future(async_func())
    assert app._is_running

Testing this with the provided test case by @vlovich proves that it works. I was also playing around and changed the seconds in the loop.call_later lines from 0.1 to 0, which of course spins the logs out much faster and without the quick fix, hitting enter ends up freezing/hanging the app completely, however with the patch, it works as expected.

I can make a pull request if this fix is all good.

Verequies commented 5 years ago

@jonathanslenders Any thoughts?