subprocess.check_output hangs when gevent support is enabled and subprocess is monkey patched

[reallistic]

Environment data

• debugpy version: 1.6.2
• OS and version:
  • VS Code 1.69.2 running on Mac OS 12.5
  • Development env - (remote ssh) Ubuntu 18.04.6 (Connected via the Remote SSH plugin)
• Python version: Python 3.9.13
• Using VS Code 1.69.2
• Using ms-python.python-2022.10.1

minimal launch.json to reproduce

{
  
    "version": "0.2.0",
    "configurations": [
        {
            "name": "Example",
            "type": "python",
            "request": "launch",
            "program": "agevent_test.py",
            "console": "integratedTerminal",
            "justMyCode": false,
            "gevent": true,
            "env": {
                "GEVENT_SUPPORT": "True",
            }
        }
  ]
}

Code to reproduce

from gevent import monkey; monkey.patch_all()

import subprocess


if __name__ == "__main__":
    resp = subprocess.check_output("tput -T xterm-256color bold".split()).decode(
        "utf-8"
    )  # nosec
    print(resp)
    print("Done")

output

6.18s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds

Turning off subprocess monkey patching fixes it and allows the program to continue.

[fabioz]

I couldn't reproduce this here.

Can you send the logs for the run?

i.e.:

• Run the command Extensions: Open Extensions Folder
• Locate the Python extension directory, typically of the form ms-python.python-2022.*.****
• In that directory ensure you do not have any debug*.log files, if you do, please delete them
• Go back into VS Code and modify your launch.json to add the setting "logToFile": true, see below:

{
  
    "version": "0.2.0",
    "configurations": [
        {
            "name": "Example",
            "type": "python",
            "request": "launch",
            "program": "agevent_test.py",
            "console": "integratedTerminal",
            "justMyCode": false,
            "gevent": true,
            "logToFile": true,
            "env": {
                "GEVENT_SUPPORT": "True",
            }
        }
  ]
}

• Start debugging
• When done, go back into the extension directory and upload the debug*.log files into this GitHub issue.

[fabioz]

As a note, I was able to reproduce showing the messages:

6.18s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds

But the debugging proceeds normally and nothing hangs (and a breakpoint can be hit in print("done")).

[fabioz]

Note: I'm investigating why those messages appear in the first place (that's not expected in this case).

[fabioz]

The issue is that gevent monkey-patching seems to be fighting with the debugger monkey-patching of os functions and subprocess functions and in https://github.com/gevent/gevent/blob/5858d226045f701deb8e4b49c03db4cab63053d6/src/gevent/subprocess.py#L1647 it ends up doing a fork/exec in a way which makes our monkey-patched functions be called in that subprocess where the debugger isn't active but the code which is patched still thinks it is, so, it makes the process take longer (the execution still seems to work for me, but it really only resumes after that timeout and gives that message that shouldn't be given).

[reallistic]

I will do some additional debugging to get you an updated code snippet. In my case it seems to be messing with my fastapi server starting. To be fair, we are doing some patching to make it work with gevent but those code paths don't seem to be the ones affected.

[reallistic]

The issue here is that we are doing 8 subprocess.check_output calls whereas my example only has 1.
Running all 8 calls takes <8 minutes. A single one for me takes ~55secs.
Let me know if you would still like the extension logs.

Here is the code to reproduce:

from gevent import monkey; monkey.patch_all()

import time
import subprocess


if __name__ == "__main__":
    start = time.monotonic()
    colors = (
        "bold",
        "setaf 1",
        "setaf 2",
        "setaf 3",
        "setaf 4",
        "setaf 5",
        "setaf 6",
        "setaf 7",
    )
    for i, ccheck in enumerate(colors):
        resp = subprocess.check_output(
            f"tput -T xterm-256color {ccheck}".split()
        ).decode("utf-8")
        dur = time.monotonic() - start
        print(f"finished {i+1} of {len(colors)} after {dur}s - {resp}")

    dur = time.monotonic() - start
    print(f"Done in - {dur}")

and the output:

6.63s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 1 of 8 after 55.08450624498073s - 
61.71s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 2 of 8 after 110.16608179896139s - 
116.79s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 3 of 8 after 165.24690017895773s - 
171.87s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 4 of 8 after 220.3279158140067s - 
226.96s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 5 of 8 after 275.4088036689209s - 
282.04s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 6 of 8 after 330.4898691949202s - 
337.12s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 7 of 8 after 385.57144676998723s - 
392.20s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
...printed many times
5.01s - pydevd: Sending message related to process being replaced timed-out after 5 seconds
finished 8 of 8 after 440.65229009697214s - 
Done in - 440.65232879901305

[fabioz]

Yes, this is really an issue (I'm still working on this item).

What happens is that the fork is done and the monkey-patching is all in place so, in the child process the debugger tries to send a message where the debugger isn't really present before an execv, but this will never work in this case (because the debugger threads aren't really live in that process), so, the practical effect is that any execv afterwards will try to send that message and it'll always timeout (so, it'll sleep for 5 seconds).

I'm working on a fix...

[fabioz]

As a note, as a workaround you can ask the debugger not to attach to subprocesses automatically (by setting "subProcess": false in your launch configuration).

[fabioz]

I have a preliminary fix just for this use case (when you're launching non-python processes with gevent).

If you want you can apply this change locally. See: fabioz@00834a5

It's not final (at the very minimum I still need to add tests and I want to test the functionality when a subprocess which is python -- and thus the debugger needs to be working in the child process -- while using gevent too), but you should be able to apply the fix locally in the meanwhile.

To apply the fix locally make a debug run with the contents below, open the file printed and do the changes from that commit link (as it's a 2-line change it should be pretty straightforward).

from _pydev_bundle import pydev_monkey
print(pydev_monkey.__file__)

[reallistic]

Verified the fix worked for me thanks!

[dre-gonzalez-l7]

If this is the same issue I'm thinking of, I noticed that python debug points could not be hit on the most recent version of vscode, but they were working in 1.61.2 (sep '21). Something changed after 1.61 that broke that (I'm using gunicorn with gevents on mac). Just spent the past few minutes comparing vscode versions, works in 1.61.2 and not on the latest.

[fabioz]

@dre-gonzalez-l7 I think this fix isn't really in the latest release... if you manually apply the change noted in: #1005 (comment), does it work for you?

[dre-gonzalez-l7]

@fabioz I'll have to set aside some time to try it out, not sure I'll be able to get to it (it's been a while)

[dre-gonzalez-l7]

@fabioz Can confirm, the code change fixed the issue presented here. I still can't hit python breakpoints though (I'm using Intel mac; I'm told debug breakpoints work on M1)

[starball5]

Possibly related on Stack Overflow: VSCode pydevd: Sending message related to process being replaced timed-out after 5 seconds

[mmohdnowfal]

Same issue is reproducible if any process using os.execv . There is a timeout while spawning a process

Adding the below fix to the debugpy code fixes this

Please provide a permanent fix for this issue

[memeplex]

I'm getting this all the time in my notebooks when using skopt and lgbm, whenever I had launched the debugger at some point in my session. Most of the time I have to restart the kernel because these messages clutter everything. Which makes the debugger kind of useless because I don't want to lose the state of my kernel.

[memeplex]

@fabioz sorry for insisting but as per #1005 (comment), which is still the case, I think this shouldn't be closed. Many times I've to restart a kernel after debugging because of the maddening amount of messages from pydev.

debugpy 1.8.0 with: