Occasional missing response to "configurationDone"

[int19h]

Sometimes, when receiving "configurationDone", and starting to execute user code, if the script exits almost immediately, the adapter closes the connection before the response to "configurationDone" is actually delivered to the client.

I've only seen it on CI Linux and macOS runs, and it's very rare, so it's hard to diagnose. But I suspect that this is another manifestation of pydevd messaging being asynchronous (#1699) - basically, if the process exits too fast, pydevd simply doesn't deliver the response, or delivers a partial response. The adapter then treats it as a failed response from the server, and in turn responds to IDE's "configurationDone" with failure "Server-1 disconnected unexpectedly".

Part of the problem may be that on_configurationdone_request() in pydevd_process_net_command_json.py invokes api.run() before sending the response. Perhaps that needs to be re-ordered?

[int19h]

Sample failure from a test run:

_ test_vsc_exception_options_raise_with_except[module-attach_by_socket(api)-uncaught] _
[gw3] linux -- Python 3.7.1 /home/travis/build/microsoft/ptvsd/.tox/py37-cov/bin/python
pyfile = <function pyfile.<locals>.factory at 0x7fc11c0ff378>
target = <class 'tests.debug.targets.Module'>, run = attach_by_socket(api)
raised = '', uncaught = 'uncaught'
    @pytest.mark.parametrize("raised", ["raised", ""])
    @pytest.mark.parametrize("uncaught", ["uncaught", ""])
    def test_vsc_exception_options_raise_with_except(
        pyfile, target, run, raised, uncaught
    ):
        @pyfile
        def code_to_debug():
            import debug_me  # noqa
    
            def raise_with_except():
                try:
                    raise ArithmeticError("bad code")  # @exc
                except Exception:
                    pass
    
            raise_with_except()
    
        with debug.Session() as session:
            session.expected_exit_code = some.int
            with run(session, target(code_to_debug)):
                session.request(
>                   "setExceptionBreakpoints", {"filters": list({raised, uncaught} - {""})}
                )
tests/ptvsd/server/test_exception.py:37: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
tests/debug/session.pym:548: in __exit__
    self.session.request("configurationDone")
tests/debug/session.py:404: in request
    .wait_for_response(freeze=freeze, raise_if_failed=raise_if_failed)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
self = {"seq": 4, "type": "request", "command": "configurationDone"}
freeze = True, raise_if_failed = True
    def wait_for_response(self, freeze=True, raise_if_failed=True):
        response = Response(self, some.object).wait_until_realized(freeze)
        assert response.observed
        if raise_if_failed and not response.success:
>           raise response.body
E           ptvsd.common.messaging.MessageHandlingError: Server-1 disconnected unexpectedly
tests/timeline.py:1086: MessageHandlingError

----------------------------- Captured stderr call -----------------------------
E+01.397: Traceback (most recent call last):
            File "/home/travis/build/microsoft/ptvsd/tests/ptvsd/server/test_exception.py", line 37, in test_vsc_exception_options_raise_with_except
              "setExceptionBreakpoints", {"filters": list({raised, uncaught} - {""})}
            File "/home/travis/build/microsoft/ptvsd/tests/debug/session.py", line 548, in __exit__
              self.session.request("configurationDone")
            File "/home/travis/build/microsoft/ptvsd/tests/debug/session.py", line 404, in request
              .wait_for_response(freeze=freeze, raise_if_failed=raise_if_failed)
            File "/home/travis/build/microsoft/ptvsd/tests/timeline.py", line 1086, in wait_for_response
              raise response.body
          ptvsd.common.messaging.MessageHandlingError: Server-1 disconnected unexpectedly

[fabioz]

I'm taking a look at this, and now I'm making sure that the message is being sent in the socket before the process is shutdown, but the problem is that this is not enough as after writing to the socket the kernel may still take some time to actually send the message and it's still possible that the process finishes before the message is sent.

From what I read, the only way to guarantee it would be doing an additional acknowledgement (this would also fix microsoft/ptvsd#1699)... this can be implicit (with careful managing of the socket lifetime shutting down just the write on the server, acknowledging that on the client and then having the client acknowledge it and close the write too, which would then be acknowledged on the server) or by explicitly passing some message (so, the server would send an message to be acknowledged by the client and when the server receives that confirmation it can exit knowing everything is sent).

Between those I'm now more inclined to have an explicit message about the shutdown, so, pydevd would send a request to the adapter and then when the adapter sends the response it can exit cleanly.

We can either reuse a message (such as the terminate request / terminate response), which when sent from pydevd would just require the response to be sent back or create a new custom message for that.

@int19h @karthiknadig what do you think?

[int19h]

Strictly speaking, DAP already says that a debug adapter shouldn't disconnect when debuggee terminates - it should report "terminated" event when debugging is over, but it's client's prerogative to decide when to close the connection.

This is already how it works in practice between the IDE and the new adapter. What if we also make pydevd work in the same manner - i.e. block process shutdown until the client closes connection from its end?

[fabioz]

So, in this case the idea would be reporting terminated / shutdown write on the pydevd socket and wait for the adapter to close the connection on its side to actually finish the process? (I guess we would also have a timeout here in case it takes too long)

Note that at this point it'd be either blocked at atexit if it's a regular run exiting or a call to os._exit if it was a terminate request.

[int19h]

Yep.

[int19h]

This is still happening - here's pydevd log from a recent Python 3.5 run:

Using Cython speedups
pydevd: Use libraries filter: False

IDE_PROJECT_ROOTS []

LIBRARY_ROOTS ['C:\\hostedtoolcache\\windows\\Python\\3.5.4\\x64\\Lib', 'd:\\a\\1\\s\\.tox\\py35\\Lib', 'd:\\a\\1\\s\\.tox\\py35\\Lib\\site-packages', 'd:\\a\\1\\s\\.tox\\py35\\lib', 'd:\\a\\1\\s\\.tox\\py35\\lib\\site-packages']

Connecting to 127.0.0.1:2859
Connected.
Process PydevdSystemInfoRequest: {
    "arguments": {},
    "command": "pydevdSystemInfo",
    "seq": 1,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"pydevd_cmd_id": 502, "success": true, "type": "response", "request_seq": 1, "seq": 2, "command": "pydevdSystemInfo", "body": {"process": {"bitness": 64, "ppid": 1096, "pid": 5696, "executable": "d:\\a\\1\\s\\.tox\\py35\\scripts\\python.exe"}, "python": {"implementation": {"description": "CPython", "name": "cpython", "version": "3.5.4final0"}, "version": "3.5.4final0"}, "pydevd": {"usingCython": false, "usingFrameEval": false}, "platform": {"name": "win32"}}}

Process EvaluateRequest: {
    "arguments": {
        "expression": "\nif 'ptvsd' not in sys.modules:\n    sys.path.insert(0, 'd:\\\\a\\\\1\\\\s\\\\.tox\\\\py35\\\\lib\\\\site-packages')\n    try:\n        import ptvsd\n    finally:\n        del sys.path[0]\n",
        "format": {}
    },
    "command": "evaluate",
    "seq": 2,
    "type": "request"
}

processing internal command  - (<_pydevd_bundle.pydevd_comm.InternalThreadCommandForAnyThread object at 0x000001B9131FD908>,)
sending cmd -->           CMD_RETURN {"pydevd_cmd_id": 502, "success": true, "type": "response", "request_seq": 2, "seq": 4, "command": "evaluate", "body": {"presentationHint": {}, "variablesReference": 0, "result": ""}}

SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py - set_tracing_for_untraced_contexts
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py - _locked_settrace
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py - settrace
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\server\api.py - enable_attach
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\server\api.py - debug
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\__init__.py - enable_attach
Set tracing of frame: <PTVSD_TEST_DEBUG_ME> - <module>
Set tracing of frame: D:\a\1\s\tests\DEBUGGEE_PYTHONPATH\debug_me\__init__.py - <module>
SKIP set tracing of frame: <frozen importlib._bootstrap> - _call_with_frames_removed
SKIP set tracing of frame: <frozen importlib._bootstrap_external> - exec_module
SKIP set tracing of frame: <frozen importlib._bootstrap> - _load_unlocked
SKIP set tracing of frame: <frozen importlib._bootstrap> - _find_and_load_unlocked
SKIP set tracing of frame: <frozen importlib._bootstrap> - _find_and_load
Set tracing of frame: C:\Users\VssAdministrator\AppData\Local\Temp\pytest-of-unknown\pytest-0\popen-gw6\test_systemexit_module_attach_5\code_to_debug.py - <module>
Set tracing of frame: C:\hostedtoolcache\windows\Python\3.5.4\x64\Lib\runpy.py - _run_code
Set tracing of frame: C:\hostedtoolcache\windows\Python\3.5.4\x64\Lib\runpy.py - _run_module_as_main
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py - settrace
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\server\api.py - enable_attach
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\server\api.py - debug
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\__init__.py - enable_attach
SKIP set tracing of frame: <frozen importlib._bootstrap> - _call_with_frames_removed
SKIP set tracing of frame: <frozen importlib._bootstrap_external> - exec_module
SKIP set tracing of frame: <frozen importlib._bootstrap> - _load_unlocked
SKIP set tracing of frame: <frozen importlib._bootstrap> - _find_and_load_unlocked
SKIP set tracing of frame: <frozen importlib._bootstrap> - _find_and_load
Process InitializeRequest: {
    "arguments": {
        "adapterID": "test",
        "clientID": "vscode",
        "columnsStartAt1": true,
        "linesStartAt1": true,
        "pathFormat": "path",
        "supportsRunInTerminalRequest": true,
        "supportsVariableType": true
    },
    "command": "initialize",
    "seq": 3,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"pydevd_cmd_id": 502, "success": true, "type": "response", "request_seq": 3, "seq": 6, "command": "initialize", "body": {"supportsTerminateThreadsRequest": false, "supportsDataBreakpoints": false, "supportsConditionalBreakpoints": true, "supportsSetVariable": true, "supportsStepBack": false, "supportsDisassembleRequest": false, "completionTriggerCharacters": [], "supportedChecksumAlgorithms": [], "supportsConfigurationDoneRequest": true, "supportsFunctionBreakpoints": false, "supportsEvaluateForHovers": true, "supportsReadMemoryRequest": false, "supportsValueFormattingOptions": true, "supportsHitConditionalBreakpoints": true, "supportsLogPoints": true, "supportsModulesRequest": true, "supportsStepInTargetsRequest": false, "supportsDebuggerProperties": true, "supportTerminateDebuggee": true, "exceptionBreakpointFilters": [{"default": false, "filter": "raised", "label": "Raised Exceptions"}, {"default": true, "filter": "uncaught", "label": "Uncaught Exceptions"}], "pydevd": {"processId": 5696}, "supportsTerminateRequest": true, "supportsDelayedStackTraceLoading": true, "supportsSetExpression": true, "supportsExceptionInfoRequest": true, "supportsGotoTargetsRequest": true, "supportsRestartFrame": false, "supportsRestartRequest": false, "additionalModuleColumns": [], "supportsCompletionsRequest": true, "supportsLoadedSourcesRequest": false, "supportsExceptionOptions": true}}

Process AttachRequest: {
    "arguments": {
        "breakOnSystemExitZero": false,
        "debugOptions": [
            "ShowReturnValue",
            "RedirectOutput"
        ],
        "host": "127.0.0.1",
        "justMyCode": true,
        "module": [
            "code_to_debug",
            "0"
        ],
        "name": "Test",
        "port": 5684,
        "redirectOutput": true,
        "type": "python"
    },
    "command": "attach",
    "seq": 4,
    "type": "request"
}

sending cmd -->    CMD_PROCESS_EVENT {"pydevd_cmd_id": 204, "body": {"isLocalProcess": true, "systemProcessId": 5696, "startMethod": "attach", "name": "C:\\Users\\VssAdministrator\\AppData\\Local\\Temp\\pytest-of-unknown\\pytest-0\\popen-gw6\\test_systemexit_module_attach_5\\code_to_debug.py"}, "type": "event", "event": "process", "seq": 8}

pydevd: Use libraries filter: True

Show return values: True
sending cmd -->           CMD_RETURN {"pydevd_cmd_id": 502, "success": true, "type": "response", "request_seq": 4, "seq": 10, "command": "attach"}

Process SetDebuggerPropertyRequest: {
    "arguments": {
        "ideOS": "WINDOWS",
        "multiThreadsSingleNotification": true,
        "skipPrintBreakpointException": [
            "NameError"
        ],
        "skipSuspendOnBreakpointException": [
            "BaseException"
        ]
    },
    "command": "setDebuggerProperty",
    "seq": 5,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"pydevd_cmd_id": 502, "success": true, "type": "response", "request_seq": 5, "seq": 12, "command": "setDebuggerProperty", "body": {}}

File not traced (not in project - force_check_project_scope): c:\hostedtoolcache\windows\python\3.5.4\x64\lib\json\__init__.py
File not traced (not in project - force_check_project_scope): c:\hostedtoolcache\windows\python\3.5.4\x64\lib\json\encoder.py
sending cmd -->    CMD_THREAD_CREATE {"pydevd_cmd_id": 103, "body": {"reason": "started", "threadId": 1}, "type": "event", "event": "thread", "seq": 14}

Process SetExceptionBreakpointsRequest: {
    "arguments": {
        "filters": [
            "uncaught"
        ]
    },
    "command": "setExceptionBreakpoints",
    "seq": 6,
    "type": "request"
}

Exceptions to hook on terminate: {'BaseException': <_pydevd_bundle.pydevd_breakpoints.ExceptionBreakpoint object at 0x000001B913E0A630>}.
SKIP set tracing of frame: C:\hostedtoolcache\windows\Python\3.5.4\x64\Lib\threading.py - wait
SKIP set tracing of frame: C:\hostedtoolcache\windows\Python\3.5.4\x64\Lib\threading.py - wait
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py - block_until_configuration_done
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py - _wait_for_attach
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\server\api.py - wait_for_attach
SKIP set tracing of frame: d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\__init__.py - wait_for_attach
Set tracing of frame: <PTVSD_TEST_DEBUG_ME> - <module>
SKIP set tracing of frame: <frozen importlib._bootstrap> - _call_with_frames_removed
SKIP set tracing of frame: <frozen importlib._bootstrap_external> - exec_module
SKIP set tracing of frame: <frozen importlib._bootstrap> - _load_unlocked
SKIP set tracing of frame: <frozen importlib._bootstrap> - _find_and_load_unlocked
SKIP set tracing of frame: <frozen importlib._bootstrap> - _find_and_load
Set tracing of frame: C:\hostedtoolcache\windows\Python\3.5.4\x64\Lib\runpy.py - _run_module_as_main
sending cmd -->           CMD_RETURN {"pydevd_cmd_id": 502, "success": true, "type": "response", "request_seq": 6, "seq": 16, "command": "setExceptionBreakpoints"}

Process ConfigurationDoneRequest: {
    "arguments": {},
    "command": "configurationDone",
    "seq": 7,
    "type": "request"
}

sending cmd -->           CMD_RETURN {"pydevd_cmd_id": 502, "success": true, "type": "response", "request_seq": 7, "seq": 18, "command": "configurationDone"}

File traced: <PTVSD_TEST_DEBUG_ME>
File traced: d:\a\1\s\tests\debuggee_pythonpath\debug_me\__init__.py
File traced: c:\users\vssadministrator\appdata\local\temp\pytest-of-unknown\pytest-0\popen-gw6\test_systemexit_module_attach_5\code_to_debug.py
sending cmd --> CMD_WRITE_TO_CONSOLE {"pydevd_cmd_id": 116, "body": {"output": "sys.exit(0)", "category": "stdout", "source": {}}, "type": "event", "event": "output", "seq": 20}

sending cmd --> CMD_WRITE_TO_CONSOLE {"pydevd_cmd_id": 116, "body": {"output": "\n", "category": "stdout", "source": {}}, "type": "event", "event": "output", "seq": 22}

File not traced (not in project - force_check_project_scope): c:\hostedtoolcache\windows\python\3.5.4\x64\lib\runpy.py
sending cmd -->      CMD_THREAD_KILL {"pydevd_cmd_id": 104, "body": {"reason": "exited", "threadId": 1}, "type": "event", "event": "thread", "seq": 24}

pydevd.CheckAliveThread received kill signal
PyDB.dispose_and_kill_all_pydevd_threads (called from: File "d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py", line 1507, in process_internal_commands)
PyDB.dispose_and_kill_all_pydevd_threads (first call)
pydevd.stoptrace()
PyDB.dispose_and_kill_all_pydevd_threads (called from: File "d:\a\1\s\.tox\py35\lib\site-packages\ptvsd\_vendored\pydevd\pydevd.py", line 2705, in stoptrace)
PyDB.dispose_and_kill_all_pydevd_threads (already disposed - wait)
PyDB.dispose_and_kill_all_pydevd_threads waiting for pydb daemon threads to finish
The following pydb threads may not have finished correctly: pydevd.CommandThread, pydevd.Reader, pydevd.Writer
PyDB.dispose_and_kill_all_pydevd_threads timed out waiting for writer to be empty.
PyDB.dispose_and_kill_all_pydevd_threads killing thread: <PyDBCommandThread(pydevd.CommandThread, started daemon 2080)>
pydevd.CommandThread received kill signal
PyDB.dispose_and_kill_all_pydevd_threads killing thread: <ReaderThread(pydevd.Reader, started daemon 892)>
pydevd.Reader received kill signal
PyDB.dispose_and_kill_all_pydevd_threads killing thread: <WriterThread(pydevd.Writer, started daemon 2200)>
sending cmd -->             CMD_EXIT {"pydevd_cmd_id": 129, "body": {}, "type": "event", "event": "terminated", "seq": 26}

pydevd.Writer received kill signal
PyDB.dispose_and_kill_all_pydevd_threads: finished
PyDB.dispose_and_kill_all_pydevd_threads: finished

Note the part about "timed out waiting for writer to be empty". On the adapter side, it simply never receives the response:

D+00002.109: IDE[1] --> {
                 "seq": 4,
                 "type": "request",
                 "command": "configurationDone"
             }

D+00002.109: /handling microsoft/ptvsd#4 request "configurationDone" from IDE[1]/
             Server[1] <-- {
                 "seq": 7,
                 "type": "request",
                 "command": "configurationDone"
             }

D+00002.875: Exiting message loop for channel Server[1]: [WinError 10054] An existing connection was forcibly closed by the remote host

D+00002.875: Closing Server[1] message stream

The timestamps correspond to the 500ms timeout for the writer thread. So it looks like the writer thread is blocked on something. However, looking at the code, I don't see any obvious way as to how it could end up being blocked before draining the queue.

[int19h]

Dup of microsoft/ptvsd#1942

[int19h]

This is still happening in test runs.

@fabioz, given the long history of this issue and all the attempts to remedy it so far, would you say that this just has to be gracefully handled by the adapter? i.e. that if it sends "configurationDone", and instead of a response, the server just disconnects, it should assume that it ran to completion, and not report it as an error to the client?

[fabioz]

This is still happening in test runs.

@fabioz, given the long history of this issue and all the attempts to remedy it so far, would you say that this just has to be gracefully handled by the adapter? i.e. that if it sends "configurationDone", and instead of a response, the server just disconnects, it should assume that it ran to completion, and not report it as an error to the client?

Yes, I think that's a good idea.

[int19h]

The fix wasn't complete, and this still happens in test runs.