Debugger crashes randomly during stepover or stepin with breakpoint

[rADikal8e7]

Environment data

• PTVSD version: ms-python.python Version: 2020.3.71659
• OS and version: Darwin x64 19.4.0
• Python version (& distribution if applicable, e.g. Anaconda): Python 3.8.1
• Using VS Code or Visual Studio: VS code
  Version: 1.44.0-insider
  Commit: e8dbc5ea6092ba73ae70069d3e730f2cc56addff
  Date: 2020-04-03T22:09:44.908Z
  Electron: 7.1.11
  Chrome: 78.0.3904.130
  Node.js: 12.8.1
  V8: 7.8.279.23-electron.0
  OS: Darwin x64 19.4.0
• Remote - Containers : ms-vscode-remote.remote-containers Version: 0.111.0

Actual behavior

Please note all the below actions are being done when attaching to remote container.

• After the auto update of python extension to 2020.3.71659 remote debugger crashes randomly.

• When using breakpoint to pause and using stepover or stepinto sometimes the debugger randomly crashes and asks to reload the window causing lose of script execution.

• Also after the crash and the subsequent reloadtopshows that ms.python is using up ridiculous amount of CPU utilzilation.

• This goes down after a few minutes.

• These actions used to work perfectly fine with the same code base and ms.python 2020.3.69010 in the same env (remote container).

• Only changes done to vscode are the auto update of python extension and installation of gitlens extension Version: 10.2.1 on local and remote.

Expected behavior

Using breakpoint stepover or stepinto should not crash the debugger.

Steps to reproduce:

1. Load the current stable python extension 2020.3.71659 and the gitlens extension to remote container.
2. Attach to said remote container and execute any python script which uses multiprocessing module.
3. Pause in a code block and perform stepinto and stepover while there are subprocesses running in the vs code.
4. Click the stepover or stepinto icon 2 or 3 times in quick succession and the debugger appears to hang for a min before throwing the reload window error.
5. Also i see the following error on the console when the crash occurs.

Let me know what additional logs can be presented to debug this further for root cause.

[rADikal8e7]

How does one enable trace log level? I have the following for remote.containers extension
"remote.containers.logLevel": "trace"

The following message pops up during the termination.

[karthiknadig]

For the debugger you can do this by setting "logToFile": true, in the debug configuration.

        {
            "name": "Python: Current File",
            "type": "python",
            "request": "launch",
            "program": "${file}",
            "console": "integratedTerminal",
            "logToFile": true
        }

This will put the log files in ~/.vscode/extensions/ms-python.python-2020.3.71659. There should be multiple log files there all ending with *.log.

[rADikal8e7]

Thanks @karthiknadig
Added the log files in gist.
https://gist.github.com/rADikal8e7/c7334c56559290eebaace815b3e94bf6

Let me know if additional info is required.

[rADikal8e7]

i feel this is very similar to the issue that was opened in ms.python.

https://github.com/microsoft/vscode-python/issues/11022

[kzhui125]

@karrtikr @rADikal8e7 see my comment https://github.com/microsoft/vscode-python/issues/11022#issuecomment-610932930

Don't know if this is the same problem.

[fabioz]

@rADikal8e7, the log shows that you have 860 threads created (you can count the occurrences of "reason": "started" in debugpy.adapter-63821.log).

Did you actually expect to create that many threads? I believe that this is a performance issue with a particular corner case of having tons of threads (I think that the issue is actually in vscode or vscode-python itself given that you have stack traces from it, but I may be wrong).

Can you share the actual program which has this behavior? I just see many threads being created, but I don't know when that happens (if that happens during a step in/step over or if they're always there may make a difference on the use case and it'd be nice to actually reproduce it with the real use case).

Also, is the container on the same machine or in a different machine? (I think that the network speed itself could make a difference in this use case).

[int19h]

FWIW, the logs do appear to indicate some issue on VSCode side. Of note is that the last thing that was sent in the vscode log file is this:

{
    "command": "stackTrace",
    "arguments": {
        "threadId": 1,
        "startFrame": 2,
        "levels": 19
    },
    "type": "request",
    "seq": 204
}

No responses nor any further requests are logged. But the debug adapter is seeing more!

             {
                 "seq": 204,
                 "type": "request",
                 "command": "stackTrace",
                 "arguments": {
                     "threadId": 1,
                     "startFrame": 2,
                     "levels": 19
                 }
             }

             {
                 "seq": 205,
                 "type": "request",
                 "command": "scopes",
                 "arguments": {
                     "frameId": 404
                 }
             }

             {
                 "seq": 206,
                 "type": "request",
                 "command": "next",
                 "arguments": {
                     "threadId": 1
                 }
             }

             {
                 "seq": 1036,
                 "type": "response",
                 "request_seq": 204,
                 "success": true,
                 "command": "stackTrace",
                 "body": {
                     "stackFrames": [],
                     "totalFrames": 2
                 }
             }

             {
                 "seq": 1037,
                 "type": "response",
                 "request_seq": 205,
                 "success": true,
                 "command": "scopes",
                 "body": {
                     "scopes": [
                         {
                             "name": "Locals",
                             "variablesReference": 404,
                             "expensive": false,
                             "source": {}
                         }
                     ]
                 }
             }

             {
                 "seq": 1038,
                 "type": "response",
                 "request_seq": 206,
                 "success": true,
                 "command": "next"
             }

             {
                 "seq": 1039,
                 "type": "event",
                 "event": "continued",
                 "body": {
                     "threadId": 403,
                     "allThreadsContinued": true
                 }
             }

             {
                 "seq": 1040,
                 "type": "event",
                 "event": "stopped",
                 "body": {
                     "reason": "step",
                     "threadId": 1,
                     "preserveFocusHint": false,
                     "allThreadsStopped": true
                 }
             }

So it had a bunch more requests from the client, and responded to all of them. Then nothing happens for almost 45 seconds in the adapter; and after that, it notices that connection is closed from the other end, and exits.

So I think the question here is why VSCode suddenly stopped logging after sending message with id=204 (but still sent more!); and why it disconnected sometime between that and the last response that debugpy had sent - it's not clear when, because with sockets, it takes a while for a hard disconnect to be noticed by the other end.

[rADikal8e7]

@rADikal8e7, the log shows that you have 860 threads created (you can count the occurrences of "reason": "started" in debugpy.adapter-63821.log).

Did you actually expect to create that many threads? I believe that this is a performance issue with a particular corner case of having tons of threads (I think that the issue is actually in vscode or vscode-python itself given that you have stack traces from it, but I may be wrong).

Can you share the actual program which has this behavior? I just see many threads being created, but I don't know when that happens (if that happens during a step in/step over or if they're always there may make a difference on the use case and it'd be nice to actually reproduce it with the real use case).

Also, is the container on the same machine or in a different machine? (I think that the network speed itself could make a difference in this use case).

Since its not a single file but in house framework with multiple libraries its not easy to share the program. The program flow goes something like this.

• Start main thread.

• start 2 secondary threads

• Do something in the main thread while the 2 secondary threads are running in the background.

• close the 2 secondary threads once they are done or a set duration is up.

• continue with the main thread and repeat opening 2 new secondary threads and close them until the main thread execution is complete.

860 threads is def not possible. At most it should have 8 processes running at once. It is possible that i may have shutdown the script while it is still executing and started a new iteration.
Is it possible vscode still keeps looking to connect back to the orphaned processes.

The container is in a remote server. However i dont think network speed is an issue since i have a pretty stable connection to the box.

How do i cleanup the stale connections if any from vs code?

[rADikal8e7]

@fabioz everytime i press debug it goes to a new log file or every time i restart vscode it starts a new log?

if its the latter then i guess everytime for the multiple times i ran the script or ended the script abruptly it has recorded the threads into the log file and the aggregate may be the 860 threads that you see. It should definitely be not possible in a single run to create 860 threads.

[fabioz]

@rADikal8e7 Usually it should go to a different log file (since it appends the pid).

If you want to double check, please remove all logs, do a single launch and then provide what's generated.

[rADikal8e7]

@int19h Perhaps there is a better way to triage this? If so please let me know the steps and logs to keep a lookout for.

The uncertainty that the vs code may reload during usage of breakpoints is really killing my debug capability.

Oh also without using debugger breakpoint if i just execute the script on vscode it works just fine.

[int19h]

First let's make sure that we have consistent logs for the repro - if it's a consistent repro, deleting existing logs and re-running will do it, as @fabioz suggested. Or you can take a look at timestamps to see which logs belong to the same debug session.

[rADikal8e7]

@fabioz Yep you were right! it does create a new log set for every launch. Then i dont see how it created 860 threads. here are the latest logs of the crash after a single launch with 2 breakpoints in the code.

https://gist.github.com/rADikal8e7/eb34f761ce8be745c61d96fe6e7ffad5

From the adapter.log i see that it starts 868 threads and exits 854 threads... Not sure why it needs so many and i dont see my code generating that many. All i see is it occasionally starts 2 processes and shuts them while keeping an additional sub process running in the background along with the main process.

[rADikal8e7]

Observed the following

• once the breakpoint is hit a debugger attached pops up in the console and every subsequent stepover or stepinto generates a debugger attached in the console. Even when the step finishes it generates the same message. After a few steps it tries to reconnect and hangs and the terminate signal is sent.

I am going to check if this is only when it hits the multiprocessing code or even during regular code step. Any and all suggestions are welcome.

[fabioz]

From the logs it seems that it creates a thread and exits it right away (when asking for threads it is always returning 2 threads).

So, some things to check:

1. Run a simple multiprocessing example and see if that works... say:

from multiprocessing import Process, Queue
import random

def rand_num():
    num = random.random()
    print(num)

if __name__ == "__main__":
    queue = Queue()

    processes = [Process(target=rand_num, args=()) for x in range(4)]

    for p in processes:
        p.start()

    for p in processes:
        p.join()

2. It'd be nice if you could try to change your code so that it doesn't keep creating a new thread all the time to see if this could be the reason.

To know where is your thread being created, you can change the threading module to add the code below after the Thread.start function def (replace '/some/path/log_thread_start.txt' with some path in your machine).

    _real_start = start
    def start(self):
        try:
            lock = self.__class__.__lock
        except:
            lock = self.__class__.__lock = Lock()
        import traceback

        with lock:
            with open('/some/path/log_thread_start.txt', 'a+') as stream:
                traceback.print_stack(file=stream)

        self._real_start()

With that you should be able to see where the thread is being created... the change afterwards would probably be creating a single thread where you submit commands through a queue instead of creating a new thread every time.... I understand real code may be tricky here, but maybe something in the lines of the code below could help (it doesn't have to be the final code, just enough to know if this could be the reason the debugger is breaking in your scenario):

import threading
def process_queue_in_thread(queue):
    while True:
        c = queue.get()
        try:
            c()
        finally:
            queue.task_done()


from queue import Queue
queue = Queue()
t = threading.Thread(target=process_queue_in_thread, args=(queue,))
t.daemon = True
t.start()

queue.put(lambda: print('task1'))
queue.put(lambda: print('task2'))
queue.put(lambda: print('task3'))

with queue.all_tasks_done:
    queue.all_tasks_done.wait()