Debugging test in VS Code does not work

[asipras]

Environment data

Version: 1.43.1 (user setup)
Commit: fe22a9645b44368865c0ba92e2fb881ff1afce94
Date: 2020-03-18T07:01:20.184Z
Electron: 7.1.11
Chrome: 78.0.3904.130
Node.js: 12.8.1
V8: 7.8.279.23-electron.0
OS: Windows_NT x64 10.0.18363

• Python version (& distribution if applicable, e.g. Anaconda): Python Anaconda 3.7.6 64-bit
• Type of virtual environment used (N/A | venv | virtualenv | conda | ...): Anaconda 1.9.12
• Relevant/affected Python packages and their versions: Python 2020.3.69010
• Relevant/affected Python-related VS Code extensions and their versions: Python 2020.3.69010

Expected behaviour

Debugging test should work.

Actual behaviour

Debugging test does not work. VS code shows error dialog. See in reproduction steps for more details. If I run the test without debugger the tests runs as expected.

Steps to reproduce:

Try to debug tests using unit test library, Click on the small bug icon for an individual test to debug.
I get a dialog box error saying Invalid message: Duplicate entries in "env". The two options i get are Open launch.json and Cancel.

I have checked my lauch.json and I do not have duplicate entries for any env variable.

Logs

ERR timeout after 500 ms: Error: timeout after 500 ms
at t.RawDebugSession.handleErrorResponse (file:///C:/Users/AP/AppData/Local/Programs/Microsoft VS Code/resources/app/out/vs/workbench/workbench.desktop.main.js:2954:952)
at file:///C:/Users/AP/AppData/Local/Programs/Microsoft VS Code/resources/app/out/vs/workbench/workbench.desktop.main.js:2954:250
at async t.RawDebugSession.shutdown (file:///C:/Users/AP/AppData/Local/Programs/Microsoft VS Code/resources/app/out/vs/workbench/workbench.desktop.main.js:2952:336)

### Settings.json

{
    "python.testing.pytestArgs": [
        "tests"
    ],
    "python.testing.unittestEnabled": false,
    "python.testing.nosetestsEnabled": false,
    "python.testing.pytestEnabled": true
}

[lorenzo-cavazzi]

Same Python extension version 2020.3.69010 and the same problem with debugging pytest tests.
In my case, I can't see any error log even when selecting Python Test Log as output (Is there another way to see complete logs?). When running the tests without debugging, everything works fine and I can see something logged in the console.
For some reason, trying to install a different version of the Python extension doesn't work.
Everything used to work until a few days ago when I was using the extension version 2020.2.64397

My system is different, here are the details

Version: 1.42.1
Commit: c47d83b293181d9be64f27ff093689e8e7aed054
Date: 2020-02-17T09:32:31.598Z
Electron: 6.1.9
Chrome: 76.0.3809.146
Node.js: 12.4.0
V8: 7.6.303.31-electron.0
OS: Linux x64 5.5.8-1-MANJARO

I am using pipenv, so I am using venv (the python version selected by VScode is correct).

[kimadeline]

Hello @asipras and @lorenzo-cavazzi, thank you for reaching out.

Can I ask you both to provide the following:

• A sample repo (just the .vscode/settings.json is sadly not enough for me to replicate this issue, I can debug tests correctly);
• The content of the Python output panel (View→Output, change the drop-down the upper-right of the Output panel to Python).

Can you also confirm that if you downgrade to the previous release of the extension (2020.2.64397) you can debug tests correctly:

@lorenzo-cavazzi what do you mean by that:

For some reason, trying to install a different version of the Python extension doesn't work.

Thanks!

[asipras]

@kimadeline thanks for looking into this. I did downgrade to the previous version of python extension 2020.2.64397 and now i am able to debug the tests.

I also did some debugging with the latest version of python extension 2020.3.69010. I was able to debug a simple test (does not reference any 3rd party modules numpy, scipy, etc.) by invoking VS code from normal command prompt. However when I invoked VS code using Anaconda prompt/terminal I got the error message mentioned above.

The log from the python output panel.

> ~\Anaconda3\envs\mounthood-dev\python.exe -m site --user-site
cwd: c:\src\Test
> ~\Anaconda3\envs\mounthood-dev\python.exe -m site --user-site
cwd: c:\src\Test
> ~\Anaconda3\envs\mounthood-dev\python.exe completion.py
cwd: c:\Users\asif.prasla\.vscode\extensions\ms-python.python-2020.3.69010\pythonFiles
> ~\Anaconda3\envs\mounthood-dev\python.exe completion.py
cwd: c:\Users\asif.prasla\.vscode\extensions\ms-python.python-2020.3.69010\pythonFiles
> ~\Anaconda3\envs\mounthood-dev\python.exe -m pylint --disable=all --enable=F,unreachable,duplicate-key,unnecessary-semicolon,global-variable-not-assigned,unused-variable,unused-wildcard-import,binary-op-exception,bad-format-string,anomalous-backslash-in-string,bad-open-mode,E0001,E0011,E0012,E0100,E0101,E0102,E0103,E0104,E0105,E0107,E0108,E0110,E0111,E0112,E0113,E0114,E0115,E0116,E0117,E0118,E0202,E0203,E0211,E0213,E0236,E0237,E0238,E0239,E0240,E0241,E0301,E0302,E0303,E0401,E0402,E0601,E0602,E0603,E0604,E0611,E0632,E0633,E0701,E0702,E0703,E0704,E0710,E0711,E0712,E1003,E1101,E1102,E1111,E1120,E1121,E1123,E1124,E1125,E1126,E1127,E1128,E1129,E1130,E1131,E1132,E1133,E1134,E1135,E1136,E1137,E1138,E1139,E1200,E1201,E1205,E1206,E1300,E1301,E1302,E1303,E1304,E1305,E1306,E1310,E1700,E1701 --msg-template='{line},{column},{category},{symbol}:{msg}' --reports=n --output-format=text c:\src\Test\tests\test_one.py
cwd: c:\src\Test
> ~\Anaconda3\envs\mounthood-dev\python.exe -m pylint --disable=all --enable=F,unreachable,duplicate-key,unnecessary-semicolon,global-variable-not-assigned,unused-variable,unused-wildcard-import,binary-op-exception,bad-format-string,anomalous-backslash-in-string,bad-open-mode,E0001,E0011,E0012,E0100,E0101,E0102,E0103,E0104,E0105,E0107,E0108,E0110,E0111,E0112,E0113,E0114,E0115,E0116,E0117,E0118,E0202,E0203,E0211,E0213,E0236,E0237,E0238,E0239,E0240,E0241,E0301,E0302,E0303,E0401,E0402,E0601,E0602,E0603,E0604,E0611,E0632,E0633,E0701,E0702,E0703,E0704,E0710,E0711,E0712,E1003,E1101,E1102,E1111,E1120,E1121,E1123,E1124,E1125,E1126,E1127,E1128,E1129,E1130,E1131,E1132,E1133,E1134,E1135,E1136,E1137,E1138,E1139,E1200,E1201,E1205,E1206,E1300,E1301,E1302,E1303,E1304,E1305,E1306,E1310,E1700,E1701 --msg-template='{line},{column},{category},{symbol}:{msg}' --reports=n --output-format=text c:\src\Test\tests\test_one.py
cwd: c:\src\Test
> conda env list
##########Linting Output - pylint##########

--------------------------------------------------------------------

Your code has been rated at 10.00/10 (previous run: 10.00/10, +0.00)



> ~\Anaconda3\envs\mounthood-dev\python.exe c:\Users\asif.prasla\.vscode\extensions\ms-python.python-2020.3.69010\pythonFiles\testing_tools\run_adapter.py discover pytest -- --rootdir c:\src\Test -s --cache-clear tests
cwd: c:\src\Test
> ~\Anaconda3\envs\mounthood-dev\python.exe -c "import notebook"
> ~\Anaconda3\envs\mounthood-dev\python.exe -c "import jupyter"

[lorenzo-cavazzi]

@kimadeline thanks for taking the time to look into this.

First, I updated my system and VScode to be on the latest version, these are the info

Version: 1.43.1
Commit: fe22a9645b44368865c0ba92e2fb881ff1afce94
Date: 2020-03-21T21:58:41.223Z
Electron: 7.1.14
Chrome: 78.0.3904.130
Node.js: 12.8.1
V8: 7.8.279.23-electron.0
OS: Linux x64 5.5.11-1-MANJARO

This is my settings.json. The virtualenv is created through pipenv

{
    "python.linting.pylintEnabled": false,
    "python.linting.flake8Enabled": true,
    "python.linting.enabled": true,
	"python.pythonPath": "/home/lorenzo/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python",
    "python.testing.unittestEnabled": false,
    "python.testing.nosetestsEnabled": false,
    "python.testing.pytestEnabled": true,
    "python.formatting.provider": "yapf"
}

This is a repo that gives me issues when trying to debug tests https://github.com/SwissDataScienceCenter/renku-python
Let's say I try to debug test_init_repository. When I click on Run Test, the test is marked as succesfull and the Python output panel is

> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -m pytest --rootdir ~/development/sdsc/renku-python --junitxml=/tmp/tmp-3682KwykJulSvoSV.xml ./tests/core/management/test_repository.py::test_init_repository
cwd: ~/development/sdsc/renku-python

When clicking on Debug Test with a breakpoint anywhere in the code, let's say at line 27, the debug shorty start (I can see the buttons "play", "stop", ... on the top) but it stops after 1 or 2 seconds without any warning. There is no output at all in the Python output panel.

Not sure if this is useful, but the initial output I see in the Python output panel after starting VScode is the following

User belongs to experiment group 'ShowPlayIcon - start'
User belongs to experiment group 'ShowExtensionSurveyPrompt - control'
User belongs to experiment group 'DebugAdapterFactory - experiment'
User belongs to experiment group 'PtvsdWheels37 - experiment'
User belongs to experiment group 'Reload - control'
User belongs to experiment group 'LS - control'
User belongs to experiment group 'UseTerminalToGetActivatedEnvVars - control'
User belongs to experiment group 'WebHostNotebook - control'
User belongs to experiment group 'CollectLSRequestTiming - control'
User belongs to experiment group 'CollectNodeLSRequestTiming - experiment'
> conda --version
> pyenv root
> python3.7 -c "import sys;print(sys.executable)"
> python3.6 -c "import sys;print(sys.executable)"
> python3 -c "import sys;print(sys.executable)"
> python2 -c "import sys;print(sys.executable)"
> python -c "import sys;print(sys.executable)"
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -c "import sys;print(sys.executable)"
> conda info --json
> pipenv --version
cwd: ~/development/sdsc/renku-python
> pipenv --version
cwd: ~/development/sdsc/renku-python
> pipenv --venv
cwd: ~/development/sdsc/renku-python
> pipenv --venv
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-notebooks-4n1SxYW5/bin/python -c "import notebook"
> ~/.local/share/virtualenvs/renku-notebooks-4n1SxYW5/bin/python -c "import jupyter"
> pipenv --py
cwd: ~/development/sdsc/renku-python
> pipenv --py
cwd: ~/development/sdsc/renku-python
Starting Jedi Python language engine.
> ~/.local/share/virtualenvs/renku-notebooks-4n1SxYW5/bin/python -m jupyter kernelspec --version
> conda --version
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python ~/.vscode-oss/extensions/ms-python.python-2020.3.69010/pythonFiles/testing_tools/run_adapter.py discover pytest -- --rootdir ~/development/sdsc/renku-python -s --cache-clear
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -c "import sys;print(sys.prefix)"
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -c "import sys;print(sys.prefix)"
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -c "import sys;print(sys.executable)"
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -c "import sys;print(sys.executable)"
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -c "from distutils.sysconfig import get_python_lib; print(get_python_lib())"
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -c "from distutils.sysconfig import get_python_lib; print(get_python_lib())"
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -m site --user-site
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -m site --user-site
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python completion.py
cwd: ~/.vscode-oss/extensions/ms-python.python-2020.3.69010/pythonFiles
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python completion.py
cwd: ~/.vscode-oss/extensions/ms-python.python-2020.3.69010/pythonFiles
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -m flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/development/sdsc/renku-python/tests/cli/test_init.py
cwd: ~/development/sdsc/renku-python
> ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -m flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/development/sdsc/renku-python/tests/cli/test_init.py
cwd: ~/development/sdsc/renku-python
##########Linting Output - flake8##########

Even when downgrading the Python extension to 2020.2.64397, I get the very same behavior. Sorry for my previous statement, I was convinced it was related to the Python extension version since debugging tests stopped working the same day the extension was updated.

Breakpoints somewhere else in the code seem to work when debugging with the remote attach, so the issue seems to be limited to debugging tests. At this point, I believe this is related to my system, but any help in further understanding how to fix this would be greatly appreciated.

[lorenzo-cavazzi]

I have tried on another system (Ubuntu 18.04) and I initially got the very same result.
After trying many things, I was able to debug by commenting out in pytest.ini the line addopts = --flake8 --pep8 [...] 🙌

For some reason, this seems to work on Ubuntu but not on my initial system Manjaro 😭 .
I also tried to uninstall VSCode and remove the config files ($HOME/.vscode and $HOME/.config/Code), but this didnt't help.

I am wondering if there is a detailed log I can look at to get extra infomation 🤔

[kimadeline]

@asipras Can you add the following configuration to your launch.json:

        {
            "name": "Python: Test debug config",
            "type": "python",
            "request": "test",
            "console": "integratedTerminal",
            "logToFile": true
        }

Try debugging your tests, and copy here the content of the debugpy*.log file from the extension folder.

@lorenzo-cavazzi are you getting the same Duplicate entries in "env" message? If that's the case, there is something else going on in your setup that's not related to the extension, because it's a Windows-specific error message from the debugger:

https://github.com/microsoft/debugpy/blob/69db68a5f9aff6c1dfd955c8934c753212f94633/src/debugpy/launcher/handlers.py#L110-L119

[lorenzo-cavazzi]

No, I don't get that message. I guess my problem is unrelated to @asipras 's one

[lorenzo-cavazzi]

Other info: if I open the Developer Tools I get the following message when successfully running the tests

[Extension Host] Info Python Extension: 2020-03-25 11:24:26: getActivatedEnvironmentVariables, Class name = C, completed in 0ms, has a truthy return value, Arg 1: <Uri:/home/lorenzo/development/sdsc/renku-python>, Arg 2: undefined, Arg 3: undefined
console.ts:137 [Extension Host] Info Python Extension: 2020-03-25 11:24:26: > ~/.local/share/virtualenvs/renku-python-WcnE3QeY/bin/python -m pytest --rootdir ~/development/sdsc/renku-python --junitxml=/tmp/tmp-10951bUxBnRjlaHFD.xml ./tests/core/management/test_repository.py::test_init_repository
console.ts:137 [Extension Host] Info Python Extension: 2020-03-25 11:24:26: cwd: ~/development/sdsc/renku-python

and I get this error when trying to debugging the test

ERR timeout after 500 ms: Error: timeout after 500 ms
    at t.RawDebugSession.handleErrorResponse (file:///usr/lib/code/out/vs/workbench/workbench.desktop.main.js:2954:952)
    at file:///usr/lib/code/out/vs/workbench/workbench.desktop.main.js:2954:250
    at async t.RawDebugSession.shutdown (file:///usr/lib/code/out/vs/workbench/workbench.desktop.main.js:2952:336)

[lorenzo-cavazzi]

Here with more details from the Log (Window)

[2020-03-25 15:05:19.148] [renderer1] [error] timeout after 500 ms: Error: timeout after 500 ms
    at t.RawDebugSession.handleErrorResponse (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:2954:952)
    at file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:2954:250
    at async t.RawDebugSession.shutdown (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:2952:336)
[2020-03-25 15:05:20.859] [renderer1] [error] TreeError [CustomView] Data tree node not found: [object Object]: Error: TreeError [CustomView] Data tree node not found: [object Object]
    at H.getDataNode (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:1097:771)
    at H._updateChildren (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:1095:64)
    at H.updateChildren (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:1094:798)
    at file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:5773:30
    at Array.map (<anonymous>)
    at G.doRefresh (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:5773:21)
    at G.refresh (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:5772:111)
    at p.$refresh (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:3671:510)
    at g._doInvokeHandler (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:3681:363)
    at g._invokeHandler (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:3681:55)
    at g._receiveRequest (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:3679:739)
    at g._receiveOneMessage (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:3678:518)
    at file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:3676:754
    at c.fire (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:110:24)
    at v.fire (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:382:801)
    at t.PersistentProtocol._receiveMessage (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:387:276)
    at file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:384:321
    at c.fire (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:110:24)
    at g.acceptChunk (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:380:306)
    at file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:379:657
    at Socket.t (file:///opt/visual-studio-code/resources/app/out/vs/workbench/workbench.desktop.main.js:390:450)
    at Socket.emit (events.js:203:13)
    at addChunk (_stream_readable.js:295:12)
    at readableAddChunk (_stream_readable.js:276:11)
    at Socket.Readable.push (_stream_readable.js:210:10)
    at Pipe.onStreamRead (internal/stream_base_commons.js:166:17)

P.S. sorry for the spam, I am really mad about this, I tried so many things to fix... 🤦‍♂️