Hang with "redirectOutput":true and too much output

[oliviercwa]

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]

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

[ssouques]

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]

@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]

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]

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]

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

[int19h]

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]

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]

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

[oliviercwa]

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]

@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.