patch_stdout corrupts terminal output if lots of output

[vlovich]

Run this example program on OSX 10.13.5 terminal & a bunch of garbage escaped escape codes are printed to the screen.

from prompt_toolkit.completion import WordCompleter
from prompt_toolkit.eventloop.defaults import use_asyncio_event_loop
from prompt_toolkit.patch_stdout import patch_stdout
from prompt_toolkit.shortcuts import CompleteStyle
from prompt_toolkit.shortcuts.prompt import prompt
from threading import Thread
from prompt_toolkit.output.vt100 import Vt100_Output

import time

def spam_print():
  while True:
    print("This is spam")

Thread(target=spam_print, daemon=True).start()

while True:
  with patch_stdout():
    prompt("> ", rprompt="test", complete_style=CompleteStyle.MULTI_COLUMN,
           completer=WordCompleter(list(chr(c) * 20 for c in range(ord("a"), ord("z")))))

Example corruption pasted below. Sometimes the terminal will even output the bell sound which to me indicates this corruption also sometimes manifests as the escape codes being written raw to the terminal. I have been unable to track down where/how the escape codes/buffer corruption is coming in (looks fine AFAICT within the patch proxy).

This is spam
This is spam
This is spam
^[[57;1R^[[51;9R^[[51;17R^[[51;26R^[[51;35R^[[51;44R^[[51;53R^[[51;62R^[[51;71R^[[51;80R^[[51;89R^[[51;98R^[[51;107R^[[51;117R^[[51;127R^[[51;137R^[[51;147R^[[51;157R^[[51;167R^[[51;177R^[[51;187R^[[51;197R^This is spam
^[[57;1R^[[51;9R^[[51;17R^[[51;26R^[[51;35R^[[51;44R^[[51;53R^[[51;62R^[[51;71R^[[51;80R^[[51;89R^[[51;98R^[[51;107R^[[51;117R^[[51;127R^[[51;137R^[[51;147R^[[51;157R^[[51;167R^[[51;177R^[[51;187R^[[51;197R^This is spam
^[[57;1R^[[51;9R^[[51;17R^[[51;26R^[[51;35R^[[51;44R^[[51;53R^[[51;62R^[[51;71R^[[51;80R^[[51;89R^[[51;98R^[[51;107R^[[51;117R^[[51;127R^[[51;137R^[[51;147R^[[51;157R^[[51;167R^[[51;177R^[[51;187R^[[51;197R^This is spam
^[[57;1R^[[51;9R^[[51;17R^[[51;26R^[[51;35R^[[51;44R^[[51;53R^[[51;62R^[[51;71R^[[51;80R^[[51;89R^[[51;98R^[[51;107R^[[51;117R^[[51;127R^[[51;137R^[[51;147R^[[51;157R^[[51;167R^[[51;177R^[[51;187R^[[51;197R^This is spam
^[[57;1R^[[51;9R^[[51;17R^[[51;26R^[[51;35R^[[51;44R^[[51;53R^[[51;62R^[[51;71R^[[51;80R^[[51;89R^[[51;98R^[[51;107R^[[51;117R^[[51;127R^[[51;137R^[[51;147R^[[51;157R^[[51;167R^[[51;177R^[[51;187R^[[51;197R^This is spam
^[[57;1R^[[51;9R^[[51;17R^[[51;26R^[[51;35R^[[51;44R^[[51;53R^[[51;62R^[[51;71R^[[51;80R^[[51;89R^[[51;98R^[[51;107R^[[51;117R^[[51;127R^[[51;137R^[[51;147R^[[51;157R^[[51;167R^[[51;177R^[[51;187R^[[51;197R^This is spam
^[[57;1R^[[51;9R^[[51;17R^[[51;26R^[[51;35R^[[51;44R^[[51;53R^[[51;62R^[[51;71R^[[51;80R^[[51;89R^[[51;98R^[[51;107R^[[51;117R^[[51;127R^[[51;137R^[[51;147R^[[51;157R^[[51;167R^[[51;177R^[[51;187R^[[51;197R^This is spam
This is spam
This is spam
This is spam
This is spam
This is spam
This is spam
This is spam
This is spam
This is spam
^[[51;3R^[[51;9R^[[51;17RThis is spam
This is spam
This is spam
This is spam

[vlovich]

One weird thing I did notice is that I CTRL-C'ed once without patch_stdout and for some reason it looked like there were a lot of threads in auto_flush_input or key_processor.py wait.
log.txt

[jonathanslenders]

Thank you for reporting!
I'm marking this as a bug, because this is not supposed to happen. But it'll take some time to investigate.

A work-around for now could be to create a simple full-screen application, with a text area on top for all the output, and an input field at the bottom for the prompt. It'll take more code then this simple prompt, but that should work fine. I believe there is an example in the examples directory.

[vlovich]

I started originally with an application but I encountered a few stumbling blocks.

1. Couldn't figure out how to get the logs to appear in the scrollback like it does with regular prompt(). I want to keep a REPL-like UI rather than having a screen-like experience. I tried with full_screen True & False so clearly it's more complicated than that.
2. I found reproing all the prompt() like functionality myself to be more challenging. Maybe I was overthinking it.

The first point is by far the biggest issue.

[vlovich]

So I looked into this a bit and it seems like the problem disappears if I comment out ask_cpr in vt100.py. Still not quite sure why it's causing corruption. Maybe it's somehow being accessed from 2 threads?

[vlovich]

Nope, doesn't appear to be a threading issue. Maybe response bytes from the CPR are being echoed somewhere for some reason?

[asmeurer]

@vlovich you can see the discussion at #456, which was a similar issue (but already solved in 2.0). Basically, CPR requests are a bit weird with the way prompt-toolkit is designed because the input and output classes have to coordinate them. The output sends the request and it has to set the terminal to echo off while the input waits for it. If the response is sent when echo is on (due to a race condition, for instance), it is printed to the terminal.

Given that you are using threads and spamming the input, a race condition seems likely here.

[vlovich]

Ah. That certainly seems like it's on the right track but I'm not sure I understand the internals enough for the explanation to make complete sense. The spam text from the background thread to the foreground happens within run_coroutine_in_terminal & thus should happen on the main thread. In fact, if you just change the background thread to write directly to stdout (without patch_stdout), then everything works more correctly. I'll try having patch_stdout check for pending CPR & attaching to the future's done callback instead if there is one.