Debug adapter protocol violations in 2018.12.1

[puremourning]

Environment data

• VS Code version: N/A (using the debug adapter with vimspector
• Extension version (available under the Extensions sidebar): 2018.12.1
• OS and version: macOS Mojave (10.14.1)
• Python version (& distribution if applicable, e.g. Anaconda): macOS system python
• Type of virtual environment used (N/A | venv | virtualenv | conda | ...): pyenv virtualenv
• Relevant/affected Python packages and their versions: any

Expected behaviour

The debug adapter should adhere to the Debug Adapter Protocol. In particular:

• It should not send multiple responses for the initialize request.
• It should include the variablesReference field in all Varables messages.
• Stack frame sources must have a name.
• Evaluations must have a string result

The previous version worked fine with vimspector.

Actual behaviour

1. The debug adapter returns multiple responses to the initialise request. Conforming debug adapter protocol clients choke on this. I suppose the specification doesn't state explicitly that this is a breach, but it seems reasonable to only reply once to a single request.
2. The variablesReference key is not always included in evaluate and variables responses. The specification lists it as mandatory.
3. The name key is not always supplied in the Source type returned from the server. The protocol states "Every source returned from the debug adapter has a name"
4. The 'result' entry in evaluate requests is returned as 'null'. There is no provision in the specification for it to be null

Logs

Duplicate response

2018-12-20 12:38:37,192 - INFO - Starting debug adapter with: {"name": "python", "command": ["node", "/Users/ben/.vscode/extensions/ms-python.python-2018.12.1/out/client/debugger/debugAdapter/main.js"]}
2018-12-20 12:38:37,196 - INFO - Debug Adapter Started
2018-12-20 12:38:37,198 - DEBUG - Sending Message: {"command": "initialize", "arguments": {"adapterID": "python", "clientID": "vimspector", "clientName": "vimspector", "linesStartAt1": true, "columnsStartAt1": true, "locale": "en_GB", "pathFormat": "path", "supportsVariableType": true, "supportsVariablePaging": false, "supportsRunInTerminalRequest": true}, "seq": 0, "type": "request"}
2018-12-20 12:38:37,198 - DEBUG - Sending Message: {"command": "launch", "arguments": {"name": "Python: Current File", "type": "python", "request": "launch", "cwd": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd", "stopOnEntry": true, "console": "integratedTerminal", "debugOptions": [], "program": "/Users/ben/.pyenv/versions/ycmd-system/bin/nosetests", "args": ["-v", "--with-id", "--ignore-files=(^\\.|^setup\\.py$)", "ycmd/tests/java/get_completions_test.py"], "env": {"PYTHONPATH": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/cregex/regex_2:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/frozendict:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/jedi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/certifi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/chardet:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/idna:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/requests:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/urllib3/src:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/ycmd/third_party/waitress"}}, "seq": 1, "type": "request"}
2018-12-20 12:38:37,355 - DEBUG - Message received (raw): {"seq":1,"type":"response","request_seq":0,"command":"initialize","success":true,"body":{"supportsExceptionInfoRequest":true,"supportsConfigurationDoneRequest":true,"supportsConditionalBreakpoints":true,"supportsSetVariable":true,"supportsExceptionOptions":true,"supportsEvaluateForHovers":true,"supportsModulesRequest":true,"supportsValueFormattingOptions":true,"supportsHitConditionalBreakpoints":true,"supportsSetExpression":true,"supportsLogPoints":true,"supportTerminateDebuggee":true,"supportsCompletionsRequest":true,"exceptionBreakpointFilters":[{"filter":"raised","label":"Raised Exceptions","default":false},{"filter":"uncaught","label":"Uncaught Exceptions","default":true}]}}
2018-12-20 12:38:37,355 - DEBUG - Message received: {'seq': 1, 'type': 'response', 'request_seq': 0, 'command': 'initialize', 'success': True, 'body': {'supportsExceptionInfoRequest': True, 'supportsConfigurationDoneRequest': True, 'supportsConditionalBreakpoints': True, 'supportsSetVariable': True, 'supportsExceptionOptions': True, 'supportsEvaluateForHovers': True, 'supportsModulesRequest': True, 'supportsValueFormattingOptions': True, 'supportsHitConditionalBreakpoints': True, 'supportsSetExpression': True, 'supportsLogPoints': True, 'supportTerminateDebuggee': True, 'supportsCompletionsRequest': True, 'exceptionBreakpointFilters': [{'filter': 'raised', 'label': 'Raised Exceptions', 'default': False}, {'filter': 'uncaught', 'label': 'Uncaught Exceptions', 'default': True}]}}
2018-12-20 12:38:37,372 - DEBUG - Message received (raw): {"command":"runInTerminal","arguments":{"kind":"integrated","title":"Python Debug Console","cwd":"/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd","args":["python","/Users/ben/.vscode/extensions/ms-python.python-2018.12.1/pythonFiles/ptvsd_launcher.py","--default","--client","--host","localhost","--port","55741","/Users/ben/.pyenv/versions/ycmd-system/bin/nosetests","-v","--with-id","--ignore-files=(^\\.|^setup\\.py$)","ycmd/tests/java/get_completions_test.py"],"env":{"PYTHONPATH":"/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/cregex/regex_2:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/frozendict:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/jedi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/certifi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/chardet:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/idna:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/requests:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/urllib3/src:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/ycmd/third_party/waitress","PYTHONIOENCODING":"UTF-8","PYTHONUNBUFFERED":"1"}},"type":"request","seq":2}
2018-12-20 12:38:37,372 - DEBUG - Message received: {'command': 'runInTerminal', 'arguments': {'kind': 'integrated', 'title': 'Python Debug Console', 'cwd': '/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd', 'args': ['python', '/Users/ben/.vscode/extensions/ms-python.python-2018.12.1/pythonFiles/ptvsd_launcher.py', '--default', '--client', '--host', 'localhost', '--port', '55741', '/Users/ben/.pyenv/versions/ycmd-system/bin/nosetests', '-v', '--with-id', '--ignore-files=(^\\.|^setup\\.py$)', 'ycmd/tests/java/get_completions_test.py'], 'env': {'PYTHONPATH': '/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/cregex/regex_2:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/frozendict:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/jedi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/certifi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/chardet:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/idna:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/requests:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/urllib3/src:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/ycmd/third_party/waitress', 'PYTHONIOENCODING': 'UTF-8', 'PYTHONUNBUFFERED': '1'}}, 'type': 'request', 'seq': 2}
2018-12-20 12:38:37,377 - DEBUG - Start terminal: term_start( ["python", "/Users/ben/.vscode/extensions/ms-python.python-2018.12.1/pythonFiles/ptvsd_launcher.py", "--default", "--client", "--host", "localhost", "--port", "55741", "/Users/ben/.pyenv/versions/ycmd-system/bin/nosetests", "-v", "--with-id", "--ignore-files=(^\\.|^setup\\.py$)", "ycmd/tests/java/get_completions_test.py"], {"vertical": 1, "norestore": 1, "cwd": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd", "env": {"PYTHONPATH": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/cregex/regex_2:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/frozendict:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/jedi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/jedi_deps/parso:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/certifi:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/chardet:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/idna:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/requests:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/requests_deps/urllib3/src:/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/ycmd/third_party/waitress", "PYTHONIOENCODING": "UTF-8", "PYTHONUNBUFFERED": "1"}} )
2018-12-20 12:38:37,389 - DEBUG - Sending Message: {"seq": 2, "type": "response", "request_seq": 2, "command": "runInTerminal", "body": {"processId": "37504"}, "success": true}
2018-12-20 12:38:37,837 - DEBUG - Message received (raw): {"body": {"category": "telemetry", "output": "ptvsd", "data": {"version": "4.2.0"}}, "type": "event", "event": "output", "seq": 0}
2018-12-20 12:38:37,838 - DEBUG - Message received: {'body': {'category': 'telemetry', 'output': 'ptvsd', 'data': {'version': '4.2.0'}}, 'type': 'event', 'event': 'output', 'seq': 0}
2018-12-20 12:38:37,842 - DEBUG - Message received (raw): {"request_seq": 1, "body": {}, "seq": 1, "success": true, "command": "launch", "message": "", "type": "response"}
2018-12-20 12:38:37,842 - DEBUG - Message received: {'request_seq': 1, 'body': {}, 'seq': 1, 'success': True, 'command': 'launch', 'message': '', 'type': 'response'}
2018-12-20 12:38:37,842 - DEBUG - Message received (raw): {"request_seq": 0, "body": {"supportsModulesRequest": true, "supportsConfigurationDoneRequest": true, "supportTerminateDebuggee": true, "supportsEvaluateForHovers": true, "supportsSetExpression": true, "supportsExceptionOptions": true, "exceptionBreakpointFilters": [{"filter": "raised", "default": false, "label": "Raised Exceptions"}, {"filter": "uncaught", "default": true, "label": "Uncaught Exceptions"}], "supportsCompletionsRequest": true, "supportsExceptionInfoRequest": true, "supportsLogPoints": true, "supportsValueFormattingOptions": true, "supportsHitConditionalBreakpoints": true, "supportsSetVariable": true, "supportsDebuggerProperties": true, "supportsConditionalBreakpoints": true}, "seq": 2, "success": true, "command": "initialize", "message": "", "type": "response"}
2018-12-20 12:38:37,842 - DEBUG - Message received: {'request_seq': 0, 'body': {'supportsModulesRequest': True, 'supportsConfigurationDoneRequest': True, 'supportTerminateDebuggee': True, 'supportsEvaluateForHovers': True, 'supportsSetExpression': True, 'supportsExceptionOptions': True, 'exceptionBreakpointFilters': [{'filter': 'raised', 'default': False, 'label': 'Raised Exceptions'}, {'filter': 'uncaught', 'default': True, 'label': 'Uncaught Exceptions'}], 'supportsCompletionsRequest': True, 'supportsExceptionInfoRequest': True, 'supportsLogPoints': True, 'supportsValueFormattingOptions': True, 'supportsHitConditionalBreakpoints': True, 'supportsSetVariable': True, 'supportsDebuggerProperties': True, 'supportsConditionalBreakpoints': True}, 'seq': 2, 'success': True, 'command': 'initialize', 'message': '', 'type': 'response'}
2018-12-20 12:38:37,843 - ERROR - Duplicate response: {'request_seq': 0, 'body': {'supportsModulesRequest': True, 'supportsConfigurationDoneRequest': True, 'supportTerminateDebuggee': True, 'supportsEvaluateForHovers': True, 'supportsSetExpression': True, 'supportsExceptionOptions': True, 'exceptionBreakpointFilters': [{'filter': 'raised', 'default': False, 'label': 'Raised Exceptions'}, {'filter': 'uncaught', 'default': True, 'label': 'Uncaught Exceptions'}], 'supportsCompletionsRequest': True, 'supportsExceptionInfoRequest': True, 'supportsLogPoints': True, 'supportsValueFormattingOptions': True, 'supportsHitConditionalBreakpoints': True, 'supportsSetVariable': True, 'supportsDebuggerProperties': True, 'supportsConditionalBreakpoints': True}, 'seq': 2, 'success': True, 'command': 'initialize', 'message': '', 'type': 'response'}

Missing 'variablesReference' in 'evaluate' response

2018-12-20 12:41:41,007 - DEBUG - Sending Message: {"command": "evaluate", "arguments": {"expression": "request_id", "frameId": 22, "context": "watch"}, "seq": 22, "type": "request"}
2018-12-20 12:41:41,037 - DEBUG - Message received (raw): {"request_seq": 22, "body": {"type": "NameError", "result": "NameError(\"name 'request_id' is not defined\",)"}, "seq": 32, "success": true, "command": "evaluate", "message": "", "type": "response"}
2018-12-20 12:41:41,038 - DEBUG - Message received: {'request_seq': 22, 'body': {'type': 'NameError', 'result': 'NameError("name \'request_id\' is not defined",)'}, 'seq': 32, 'success': True, 'command': 'evaluate', 'message': '', 'type': 'response'}

In reality the problem here is that request_id in this context, does exist,
but that's not a protocol violation.

Missing 'variablesReference' in 'variables' response

2018-12-20 13:01:32,207 - DEBUG - Sending Message: {"command": "variables", "arguments": {"variablesReference": 1}, "seq": 32, "type": "request"}
2018-12-20 13:01:32,228 - DEBUG - Message received (raw): {"request_seq": 32, "body": {"variables": [{"variablesReference": 2, "evaluateName": "request_data", "type": "RequestWrap", "name": "request_data", "value": "<ycmd.request_wrap.RequestWrap object at 0x110182d90>"}, {"evaluateName": "request_id", "type": "newstr", "name": "request_id", "value": "'2'"}, {"variablesReference": 3, "evaluateName": "self", "type": "JavaCompleter", "name": "self", "value": "<ycmd.completers.java.java_completer.JavaCompleter object at 0x11005e8d0>"}]}, "seq": 44, "success": true, "command": "variables", "message": "", "type": "response"}
2018-12-20 13:01:32,228 - DEBUG - Message received: {'request_seq': 32, 'body': {'variables': [{'variablesReference': 2, 'evaluateName': 'request_data', 'type': 'RequestWrap', 'name': 'request_data', 'value': '<ycmd.request_wrap.RequestWrap object at 0x110182d90>'}, {'evaluateName': 'request_id', 'type': 'newstr', 'name': 'request_id', 'value': "'2'"}, {'variablesReference': 3, 'evaluateName': 'self', 'type': 'JavaCompleter', 'name': 'self', 'value': '<ycmd.completers.java.java_completer.JavaCompleter object at 0x11005e8d0>'}]}, 'seq': 44, 'success': True, 'command': 'variables', 'message': '', 'type': 'response'}

See the 2nd entry in variables. This item is not expandable, so should have
variablesReference set to 0, not omitted.

null result in 'evaluate' response

2018-12-20 12:38:54,618 - DEBUG - Sending Message: {"command": "evaluate", "arguments": {"expression": "request_id", "frameId": 22, "context": "hover"}, "seq": 21, "type": "request"}
2018-12-20 12:38:54,659 - DEBUG - Message received (raw): {"request_seq": 21, "body": {"variablesReference": 0, "result": null}, "seq": 31, "success": true, "command": "evaluate", "message": "", "type": "response"}
2018-12-20 12:38:54,660 - DEBUG - Message received: {'request_seq': 21, 'body': {'variablesReference': 0, 'result': None}, 'seq': 31, 'success': True, 'command': 'evaluate', 'message': '', 'type': 'response'}

Missing 'name' in 'Source' under 'StackFrame'

2018-12-20 12:38:52,755 - DEBUG - Message received (raw): {"request_seq": 18, "body": {"totalFrames": 12, "stackFrames": [{"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/completers/language_server/language_server_completer.py", "sourceReference": 0}, "line": 773, "id": 22, "name": "ComputeCandidatesInner"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/completers/completer.py", "sourceReference": 0}, "line": 248, "id": 23, "name": "_GetCandidatesFromSubclass"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/completers/completer.py", "sourceReference": 0}, "line": 235, "id": 24, "name": "ComputeCandidates"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/handlers.py", "sourceReference": 0}, "line": 103, "id": 25, "name": "GetCompletions"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle/bottle.py", "sourceReference": 0}, "line": 1740, "id": 26, "name": "wrapper"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle/bottle.py", "sourceReference": 0}, "line": 862, "id": 27, "name": "_handle"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle/bottle.py", "sourceReference": 0}, "line": 954, "id": 28, "name": "wsgi"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/bottle/bottle.py", "sourceReference": 0}, "line": 979, "id": 29, "name": "__call__"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/tests/java/get_completions_test.py", "sourceReference": 0}, "line": 86, "id": 36, "name": "RunTest"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/tests/test_utils.py", "sourceReference": 0}, "line": 366, "id": 37, "name": "wrapper"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/tests/java/get_completions_test.py", "sourceReference": 0}, "line": 590, "id": 38, "name": "GetCompletions_ForceAtTopLevel_NoImport_test"}, {"column": 1, "source": {"path": "/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/ycmd/tests/java/__init__.py", "sourceReference": 0}, "line": 91, "id": 39, "name": "Wrapper"}]}, "seq": 28, "success": true, "command": "stackTrace", "message": "", "type": "response"}

I realise this is unusual (most users will be using VSCode), and I can work around all of these issues in vimspector, but the key power of DAP is client independence.

Relying on VSCode de facto behaviours makes it difficult to build and maintain independent clients.

[puremourning]

Additionally, the server seems to no longer respond to the disconnect request:

The server should response according to the protocol: https://microsoft.github.io/debug-adapter-protocol/specification#Requests_Disconnect

2018-12-20 13:52:42,709 - DEBUG - Sending Message: {"command": "disconnect", "arguments": {"terminateDebugee": true}, "seq": 34, "type": "request"}
2018-12-20 13:52:42,781 - DEBUG - Message received (raw): {"seq":0,"type":"event","event":"terminated"}
2018-12-20 13:52:42,781 - DEBUG - Message received: {'seq': 0, 'type': 'event', 'event': 'terminated'}

This makes controlling orderly closedown difficult.

[brettcannon]

Thanks for the info, but ptvsd by itself doesn't implement the Debug Adapter Protocol and our debug adapter in the extension isn't designed to be run externally. If you want to submit a PR to us or Microsoft/ptvsd then we would be happy to review it.

[puremourning]

Thanks for the tip! I will look at ptvsd!