-
-
Notifications
You must be signed in to change notification settings - Fork 132
Description
When pydevd uses sys.monitoring, a visual breakpoint that I set in VS Code to stop inside a callback function that is called by a native thread (one spawned by pthread_create rather than by threading.Thread) fails to successfully (or at least completely) attach. I can't share the source code for the extension module where we're encountering this, but if you have trouble reproducing it I can probably construct a reproducer using Cython without too much trouble. It may be relevant that the extension module where we're seeing this sends its logs to the Python logging module, so it has a pattern of running without the GIL until it wants to log something, then acquiring the GIL (and creating a threadstate) with PyGILState_Ensure, calling logging.info or some such, and then releasing the GIL (and destroying the threadstate) with PyGILState_Release.
The behavior I see is that the "call stack" window in VS Code's debugger shows the process as "paused on breakpoint", but every thread within the process as just "paused", and the "continue" button seems to have no effect for any of the threads. If I disable usage of sys.monitoring by using PYDEVD_USE_SYS_MONITORING=0 and have the native thread install the trace function by doing sys.settrace(threading._trace_hook), things work properly, so this failure seems to be unique to sys.monitoring.
In the debug output from running with PYDEVD_DEBUG=1 and DEBUGPY_LOG_STDERR="debug debug", I see this (with some confidential paths elided):
0.00s - sending cmd (http_json) --> CMD_THREAD_CREATE {"type": "event", "event": "thread", "body": {"reason": "started", "threadId": 3}, "seq": 72, "pydevd_cmd_id": 103}
0.00s - PyDB.do_wait_suspend
name: process_example_request (line: 29)
file: /<...>/request_dispatcher.py
event: line
arg: None
step: CMD_STEP_INTO (original step: <Unknown: -1>)
thread: <_DummyThread(Dummy-7, started daemon 139964549404416)>, thread id: pid_2923133_id_139964586046032, id(thread): 139964586046032
Followed by:
0.00s - Skipping per-thread thread suspend notification.
0.00s - Thread suspend mode: single notification
0.00s - Sending suspend notification.
0.00s - sending cmd (http_json) --> CMD_THREAD_SUSPEND_SINGLE_NOTIFICATION {"type": "event", "event": "stopped", "body": {"reason": "breakpoint", "threadId": 4, "preserveFocusHint": false, "allThreadsStopped": true}, "seq": 74, "pydevd_cmd_id": 157}
0.01s - Process ThreadsRequest: {
"command": "threads",
"seq": 12,
"type": "request"
}
0.00s - Processing thread <_MainThread(MainThread, started 139965439170368)> which is alive
0.00s - Processing thread <Thread(Thread-6 (_block), started 139964327130880)> which is alive
0.00s - Processing thread <_DummyThread(Dummy-8, started daemon 139964549404416)> which is alive
0.00s - sending cmd (http_json) --> CMD_RETURN {"type": "response", "request_seq": 12, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 2, "name": "Thread-6 (_block)"}, {"id": 3, "name": "Dummy-8"}]}, "seq": 76, "pydevd_cmd_id": 502}
0.04s - Process ThreadsRequest: {
"command": "threads",
"seq": 13,
"type": "request"
}
0.00s - Processing thread <_MainThread(MainThread, started 139965439170368)> which is alive
0.00s - Processing thread <Thread(Thread-6 (_block), started 139964327130880)> which is alive
0.00s - Processing thread <_DummyThread(Dummy-8, started daemon 139964549404416)> which is alive
0.00s - sending cmd (http_json) --> CMD_RETURN {"type": "response", "request_seq": 13, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 2, "name": "Thread-6 (_block)"}, {"id": 3, "name": "Dummy-8"}]}, "seq": 78, "pydevd_cmd_id": 502}
0.08s - Process ThreadsRequest: {
"command": "threads",
"seq": 14,
"type": "request"
}
0.00s - Processing thread <_MainThread(MainThread, started 139965439170368)> which is alive
0.00s - Processing thread <Thread(Thread-6 (_block), started 139964327130880)> which is alive
0.00s - Processing thread <_DummyThread(Dummy-8, started daemon 139964549404416)> which is alive
0.00s - sending cmd (http_json) --> CMD_RETURN {"type": "response", "request_seq": 14, "success": true, "command": "threads", "body": {"threads": [{"id": 1, "name": "MainThread"}, {"id": 2, "name": "Thread-6 (_block)"}, {"id": 3, "name": "Dummy-8"}]}, "seq": 80, "pydevd_cmd_id": 502}
Note that in the do_wait_suspend output, it has
<_DummyThread(Dummy-7, started daemon 139964549404416)>but in the ThreadsRequest responses it instead has
<_DummyThread(Dummy-8, started daemon 139964549404416)>That's the same id, but a different dummy name for the same thread.
I believe that what's happening here is that a native thread that gains and drops the GIL multiple times (with PyGILState_Ensure and PyGILState_Release) will wind up with different dummy thread objects assigned to it each time threading.current_thread is called after a new threadstate is created, and pydevd is caching only the first one, and failing to match it up to the ones created later.
This code seems to be related:
PyDev.Debugger/_pydevd_sys_monitoring/_pydevd_sys_monitoring.py
Lines 346 to 350 in 3030fa9
| else: | |
| # This means that the first frame is not in threading nor in pydevd. | |
| # In practice this means it's some unmanaged thread, so, creating | |
| # a dummy thread is ok in this use-case. | |
| t = threading.current_thread() |
I think that the comment saying "In practice this means it's some unmanaged thread, so, creating a dummy thread is ok in this use-case" is at least misleading, and possibly wrong: is it really OK to create a dummy thread for that use-case when a later call to threading.current_thread on the same thread could return a different dummy thread object?
I've noticed that if I set PYDEVD_USE_CYTHON=0 and then change the t = threading.current_thread() following that comment to t = None instead, then the problem goes away.