Hang with "redirectOutput":true and too much output

oliviercwa commented 4 years ago

Hello, I am debugging Python code in VS Code and and in the middle of the debugging session, at random time, it hangs. Everything is still responsive and you can interact with everything, but the execution is frozen and anything related to debugging does not evaluate. I try to press F5, click on the Start button, but the debugging session does not continue.

Notes:

It can also happen after when it hits a breakpoint and I type a debug command. Once it happens, there's a small arrow that appears to the left of the last command that was sent to the debug windows. All subsequent commands will show the same sign to the left (no evaluation performed). Also threads are shown as paused and clicking on resume does nothing. Again the VS code window is responsive, just the debugging seems frozen.
It also happens when using RUN WITHOUT DEBUGGING. But it does not happen when running outside of VS Code from a Powershell windows for example.
The only way to continue is to STOP and restart.

This is very painful as prevents the ability to debug Python in good conditions.

Environment: OS: Windows_NT x64 10.0.19041 Python: 3.7.4 64 bits VS: Version: 1.43.1 (user setup) Commit: fe22a9645b44368865c0ba92e2fb881ff1afce94 Date: 2020-03-18T07:01:20.184Z Electron: 7.1.11 Chrome: 78.0.3904.130 Node.js: 12.8.1 V8: 7.8.279.23-electron.0

karthiknadig commented 4 years ago

@oliviercwa Can you share the extension version? and also the following line from Output > Python panel?

ssouques commented 4 years ago

Hello, same issue here. I'm using extension version 2020.3.69010. And here's the capture you requested :

For information, I've been using this extension for months, and this only started today.

Thank you for your help.

karthiknadig commented 4 years ago

@ssouques @oliviercwa We will need logs to help with this. Can you add "logTofile": true to the debug configuration and share the logs? the logs should be in the extension folder, <user/home>/.vscode/extensions/<python extension>/. There will be multiple logs files, please share them all. If you can share your project or if possible create a minimal repro and share that with us (either as a github repo or as a zip)

oliviercwa commented 4 years ago

Since, it was quite painful, I have tried to disable all but one python extension, but the problem was still here. Then I tried to changed the console from "internalConsole" to "integratedTerminal" and the problem no longer happens. When I switch back to "internalConsole", it comes back immediately.

Which part of the logs do you want me to share? The log contains LOTS of confidential information include environment variables, etc.

Once it freezes, I tested the state by typing "a=10" in the debugger followed by a,, This is the end of the logs (there are a few logs about "Thread to get completions seems to have resumed already.")

debugger.vscode

46370 Client <-- Adapter:
{
    "seq": 178,
    "type": "event",
    "event": "thread",
    "body": {
        "reason": "exited",
        "threadId": 8
    }
}
46930 Client <-- Adapter:
{
    "seq": 179,
    "type": "event",
    "event": "thread",
    "body": {
        "reason": "started",
        "threadId": 9
    }
}
47039 Client --> Adapter:
{
    "command": "threads",
    "type": "request",
    "seq": 14
}
47041 Client <-- Adapter:
{
    "seq": 180,
    "type": "response",
    "request_seq": 14,
    "success": true,
    "command": "threads",
    "body": {
        "threads": [
            {
                "id": 1,
                "name": "MainThread"
            },
            {
                "id": 9,
                "name": "Thread-13"
            }
        ]
    }
}
130069 Client --> Adapter:
{
    "command": "completions",
    "arguments": {
        "text": "a",
        "column": 2,
        "line": 1
    },
    "type": "request",
    "seq": 15
}
131172 Client --> Adapter:
{
    "command": "evaluate",
    "arguments": {
        "expression": "a=10",
        "context": "repl"
    },
    "type": "request",
    "seq": 16
}
131863 Client --> Adapter:
{
    "command": "completions",
    "arguments": {
        "text": "a",
        "column": 2,
        "line": 1
    },
    "type": "request",
    "seq": 17
}
132137 Client --> Adapter:
{
    "command": "evaluate",
    "arguments": {
        "expression": "a",
        "context": "repl"
    },
    "type": "request",
    "seq": 18
}

No evaluation shown in the Debug window, just "a"

Here is the end of the output of debugpy.pydevd:


sending cmd -->           CMD_RETURN {"type": "response", "request_seq": 14, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 4, "name": "Thread-8"}]}, "seq": 42, "pydevd_cmd_id": 502}

sending cmd -->      CMD_THREAD_KILL {"type": "event", "event": "thread", "body": {"reason": "exited", "threadId": 4}, "seq": 44, "pydevd_cmd_id": 104}

sending cmd -->    CMD_THREAD_CREATE {"type": "event", "event": "thread", "body": {"reason": "started", "threadId": 5}, "seq": 46, "pydevd_cmd_id": 103}

Process ThreadsRequest: {
    "command": "threads",
    "seq": 15,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"type": "response", "request_seq": 15, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 5, "name": "Thread-9"}]}, "seq": 48, "pydevd_cmd_id": 502}

sending cmd -->      CMD_THREAD_KILL {"type": "event", "event": "thread", "body": {"reason": "exited", "threadId": 5}, "seq": 50, "pydevd_cmd_id": 104}

sending cmd -->    CMD_THREAD_CREATE {"type": "event", "event": "thread", "body": {"reason": "started", "threadId": 6}, "seq": 52, "pydevd_cmd_id": 103}

Process ThreadsRequest: {
    "command": "threads",
    "seq": 16,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"type": "response", "request_seq": 16, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 6, "name": "Thread-10"}]}, "seq": 54, "pydevd_cmd_id": 502}

sending cmd -->      CMD_THREAD_KILL {"type": "event", "event": "thread", "body": {"reason": "exited", "threadId": 6}, "seq": 56, "pydevd_cmd_id": 104}

sending cmd -->    CMD_THREAD_CREATE {"type": "event", "event": "thread", "body": {"reason": "started", "threadId": 7}, "seq": 58, "pydevd_cmd_id": 103}

Process ThreadsRequest: {
    "command": "threads",
    "seq": 17,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"type": "response", "request_seq": 17, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 7, "name": "Thread-11"}]}, "seq": 60, "pydevd_cmd_id": 502}

sending cmd -->      CMD_THREAD_KILL {"type": "event", "event": "thread", "body": {"reason": "exited", "threadId": 7}, "seq": 62, "pydevd_cmd_id": 104}

sending cmd -->    CMD_THREAD_CREATE {"type": "event", "event": "thread", "body": {"reason": "started", "threadId": 8}, "seq": 64, "pydevd_cmd_id": 103}

Process ThreadsRequest: {
    "command": "threads",
    "seq": 18,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"type": "response", "request_seq": 18, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 8, "name": "Thread-12"}]}, "seq": 66, "pydevd_cmd_id": 502}

sending cmd -->      CMD_THREAD_KILL {"type": "event", "event": "thread", "body": {"reason": "exited", "threadId": 8}, "seq": 68, "pydevd_cmd_id": 104}

sending cmd -->    CMD_THREAD_CREATE {"type": "event", "event": "thread", "body": {"reason": "started", "threadId": 9}, "seq": 70, "pydevd_cmd_id": 103}

Process ThreadsRequest: {
    "command": "threads",
    "seq": 19,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"type": "response", "request_seq": 19, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 9, "name": "Thread-13"}]}, "seq": 72, "pydevd_cmd_id": 502}

Process CompletionsRequest: {
    "arguments": {
        "column": 2,
        "line": 1,
        "text": "a"
    },
    "command": "completions",
    "seq": 20,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"type": "response", "request_seq": 20, "success": false, "command": "completions", "body": {"targets": []}, "seq": 74, "message": "Thread to get completions seems to have resumed already.", "pydevd_cmd_id": 502}

And the end of debugpy.adapter

D+00046.781: /handling microsoft/vscode-python#70 event "thread" from Server[1]/
             Client[1] <-- {
                 "seq": 179,
                 "type": "event",
                 "event": "thread",
                 "body": {
                     "reason": "started",
                     "threadId": 9
                 }
             }

D+00046.891: Client[1] --> {
                 "seq": 14,
                 "type": "request",
                 "command": "threads"
             }

D+00046.891: /handling microsoft/vscode-python#14 request "threads" from Client[1]/
             Server[1] <-- {
                 "seq": 19,
                 "type": "request",
                 "command": "threads"
             }

D+00046.891: Server[1] --> {
                 "pydevd_cmd_id": 502,
                 "seq": 72,
                 "type": "response",
                 "request_seq": 19,
                 "success": true,
                 "command": "threads",
                 "body": {
                     "threads": [
                         {
                             "id": 1,
                             "name": "MainThread"
                         },
                         {
                             "id": 9,
                             "name": "Thread-13"
                         }
                     ]
                 }
             }

D+00046.891: /handling microsoft/vscode-python#14 request "threads" from Client[1]/
             Client[1] <-- {
                 "seq": 180,
                 "type": "response",
                 "request_seq": 14,
                 "success": true,
                 "command": "threads",
                 "body": {
                     "threads": [
                         {
                             "id": 1,
                             "name": "MainThread"
                         },
                         {
                             "id": 9,
                             "name": "Thread-13"
                         }
                     ]
                 }
             }

D+00129.922: Client[1] --> {
                 "seq": 15,
                 "type": "request",
                 "command": "completions",
                 "arguments": {
                     "text": "a",
                     "column": 2,
                     "line": 1
                 }
             }

D+00129.922: /handling microsoft/vscode-python#15 request "completions" from Client[1]/
             Server[1] <-- {
                 "seq": 20,
                 "type": "request",
                 "command": "completions",
                 "arguments": {
                     "text": "a",
                     "column": 2,
                     "line": 1
                 }
             }

D+00129.922: Server[1] --> {
                 "pydevd_cmd_id": 502,
                 "seq": 74,
                 "type": "response",
                 "request_seq": 20,
                 "success": false,
                 "command": "completions",
                 "message": "Thread to get completions seems to have resumed already.",
                 "body": {
                     "targets": []
                 }
             }

ssouques commented 4 years ago

Hello,

here's a way to reproduce : https://github.com/ssouques/debug-freezepythonvscode the freeze only occurs when I start the test using the unit test feature of vs code. If I just start the python module, everything works. It looks like it freezes after printing a certain amount of data into the debug window

Regards, Seb

karthiknadig commented 4 years ago

@oliviercwa @ssouques Thank you for the details. Transferring this to debugger repo.

int19h commented 4 years ago

With "redirectOutput", we read debuggee's stdout and stderr, convert them to "output" events, and then tee them into the launcher's stdout/err.

The problem is that with "internalConsole", the launcher's stdout/err is also redirected by the adapter to its stderr. If nothing is reading from there, then the entire logical pipe gets clogged eventually - i.e. it freezes once the buffers are filled up. We are kinda assuming that adapter's stderr is going to be drained by the client, but this is not guaranteed.

The fix is for the adapter to stop trying to tee launcher's stdout to its stderr if "internalConsole" is in effect, and stdout is used for DAP. It should just dump it all to /dev/null.

oliviercwa commented 4 years ago

Just some additional information. I was actually to repro the bug even when using "integratedTerminal" or "externalTerminal". As @ssouques mentioned, it seems related to the number of data that goes through the debug output. For example, if I print a few dataframe, it hangs very rapidly.

This is quite a painful bug and slow us down enormously as there are no other options but to restart. If you know of any workaround, I will take it :) !

int19h commented 4 years ago

@oliviercwa, does it still happen if you use"redirectOutput":false?

oliviercwa commented 4 years ago

It seems to work with "redirectOutput":false. I will use it trough out the day and report back if otherwise Thank you for your help!

int19h commented 4 years ago

@oliviercwa, did you have it explicitly set to true in your launch.json before? It should default to false if you have "integratedTerminal", so you should be able to just omit it. If that's not working somehow, that would be another bug.

oliviercwa commented 4 years ago

I did not have it before, so the default value was used. I have noticed you closed the bug, but right now, we can't debug reliably using the internalConsole or integrateTerminal. Is there a plan to fix this issue?

int19h commented 4 years ago

The fix is already in master - it's in the commit referenced from the message that says that issue is closed. It'll be in the next debugpy prerelease, and from there, in the next extension release.

In the meantime, the suggested workaround is to use {"console":"integratedTerminal", "redirectOutput":false} - this should avoid the bug while still giving you access to the output of your app.

You can also use the most recent debugger bits directly from GitHub to get the fix early. Just clone this repository somewhere - say, C:\git\debugpy - and then you can do this in your launch.json:

"debugAdapterPath": "C:\git\debugpy\src\debugpy\adapter"

(However, this skips building native modules that debugger uses to speed things up, so it will be a bit slower than the version packaged with the extension.)

microsoft / debugpy

Hang with "redirectOutput":true and too much output #83