python-lsp / pylsp-mypy

Mypy plugin for the Python LSP Server.
MIT License
118 stars 35 forks source link

pylsp died whenever dmypy is enabled #52

Closed lieryan closed 1 year ago

lieryan commented 1 year ago

It seems like pylsp gets killed whenever I enabled pylsp-mypy in dmypy/daemon mode.

$ dmypy kill
$ rm -r /tmp/log.txt .dmypy.json .mypy_cache
$ cat pylsp-mypy.cfg 
{
    "enabled": True,
    "live_mode": False,
    "dmypy": True,
    "strict": True
}
$ vim   ## using vim-lsp
:LspStatus
pylsp: exited

At this point, since pylsp had died, nothing that uses pylsp works.

Toggling dmypy to False seems to allow pylsp-mypy to work again and checking type errors as expected.

$ cat pylsp-mypy.cfg 
{
    "enabled": True,
    "live_mode": False,
    "dmypy": False,
    "strict": True
}
$ vim   ## using vim-lsp
$ pgrep -lf pylsp
471433 dmypy
471933 pylsp

I don't see any obvious errors on the pylsp log file (attached).

Any idea what might be happening here or how I can help further debug this?


environment details Python: 3.10 ``` $ pip freeze docstring-to-markdown==0.11 jedi==0.18.2 mypy==0.991 mypy-extensions==0.4.3 parso==0.8.3 pluggy==1.0.0 pylsp-mypy==0.6.5 python-lsp-jsonrpc==1.0.0 python-lsp-server==1.7.0 toml==0.10.2 tomli==2.0.1 typing_extensions==4.4.0 ujson==5.7.0 ```
pylsp log file ``` $ cat /tmp/log.txt 2023-01-17 16:20:18,008 AEDT - INFO - pylsp.python_lsp - Starting PythonLSPServer IO language server 2023-01-17 16:20:18,151 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'autopep8': No module named 'pycodestyle' 2023-01-17 16:20:18,161 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'mccabe': No module named 'mccabe' 2023-01-17 16:20:18,163 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'pycodestyle': No module named 'pycodestyle' 2023-01-17 16:20:18,164 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'pydocstyle': No module named 'pydocstyle' 2023-01-17 16:20:18,165 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'pyflakes': No module named 'pyflakes' 2023-01-17 16:20:18,167 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'rope_autoimport': No module named 'rope' 2023-01-17 16:20:18,168 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'rope_completion': No module named 'rope' 2023-01-17 16:20:18,169 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'rope_rename': No module named 'rope' 2023-01-17 16:20:18,170 AEDT - INFO - pylsp.config.config - Failed to load pylsp entry point 'yapf': No module named 'yapf' 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin flake8 from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin folding from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_completion from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_definition from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_highlight from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_hover from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_references from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_rename from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_signature_help from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin jedi_symbols from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin preload from 2023-01-17 16:20:18,203 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin pylint from 2023-01-17 16:20:18,204 AEDT - INFO - pylsp.config.config - Loaded pylsp plugin pylsp_mypy from 2023-01-17 16:20:18,204 AEDT - INFO - pylsp_mypy.plugin - init workspace = /home/lieryan/tmp/dmypy-test 2023-01-17 16:20:18,204 AEDT - INFO - pylsp_mypy.plugin - mypyConfigFile = None configuration = {'enabled': True, 'live_mode': False, 'dmypy': True, 'strict': True} 2023-01-17 16:20:18,204 AEDT - INFO - pylsp.config.config - Disabled plugins: [, ] 2023-01-17 16:20:18,208 AEDT - INFO - pylsp.python_lsp - Server capabilities: {'codeActionProvider': True, 'codeLensProvider': {'resolveProvider': False}, 'completionProvider': {'resolveProvider': True, 'triggerCharacters': ['.']}, 'documentFormattingProvider': True, 'documentHighlightProvider': True, 'documentRangeFormattingProvider': True, 'documentSymbolProvider': True, 'definitionProvider': True, 'executeCommandProvider': {'commands': []}, 'hoverProvider': True, 'referencesProvider': True, 'renameProvider': True, 'foldingRangeProvider': True, 'signatureHelpProvider': {'triggerCharacters': ['(', ',', '=']}, 'textDocumentSync': {'change': 2, 'save': {'includeText': True}, 'openClose': True}, 'workspace': {'workspaceFolders': {'supported': True, 'changeNotifications': True}}, 'experimental': {}} 2023-01-17 16:20:18,714 AEDT - INFO - pylsp_mypy.plugin - lint settings = {'enabled': True, 'live_mode': False, 'dmypy': True, 'strict': True} document.path = /home/lieryan/tmp/dmypy-test/foobar.py is_saved = True 2023-01-17 16:20:18,831 AEDT - INFO - pylsp_mypy.plugin - restarting dmypy from status: 2 message: No status file found via path 2023-01-17 16:20:19,148 AEDT - INFO - pylsp_mypy.plugin - dmypy run args = ['--status-file', '.dmypy.json', 'run', '--', '--show-column-numbers', '/home/lieryan/tmp/dmypy-test/foobar.py', '--strict'] via path 2023-01-17 16:20:20,968 AEDT - INFO - pylsp_mypy.plugin - pylsp-mypy len(diagnostics) = 1 ```
vim-lsp config ```vim autocmd User lsp_setup call lsp#register_server({ \ 'name': 'pylsp', \ 'cmd': {server_info->['pylsp', '-v', '--log-file', '/tmp/log.txt']}, \ 'allowlist': ['python'], \ }) ```
Richardk2n commented 1 year ago

First question, that comes to mind would be: Why is there a dmypy process running if you set it to false? Do you have anything else installed, that might interact with dmypy? Do you have your development venv active? What does which dmypy return? The log states, that one diagnostic (the first) has finished. The second one seems not to have started yet.

If you know where pylsp-mypy is installed please go to the plugin.py file and add a log.info("Test") call at the beginning of pylsp_lint (line 147 for the latest version), retest and show the log. I wonder if it even runs again.

lieryan commented 1 year ago

Hi @Richardk2n, thanks for getting back to me.

I had a chance to debug this further and I think I have a bit of a clue now. First, I tried running pylsp in tcp mode:

pylsp -v --tcp --port 8772

and this issue didn't happen. So that's strange.

So, I returned pylsp to run on stdout mode and add some code to start a remote debugger, I found that it died at this line 108 in pylsp-jsonrpc:

self._wfile.write(response.encode('utf-8')) 

Which is basically just writing a string to stdout, it's so I printed what it is writing (response):

Content-Length: 371
Content-Type: application/vscode-jsonrpc; charset=utf8

{"jsonrpc":"2.0","method":"textDocument\/publishDiagnostics","params":{"uri":"file:\/\/\/home\/lieryan\/tmp\/dmypy-test\/foobar.py","diagnostics":[{"source":"mypy","range":{"start":{"line":0,"character":9},"end":{"line":0,"character":10}},"message":"Incompatible types in assignment (expression has type \"str\", variable has type \"int\")  [assignment]","severity":1}]}}

that seems like a completely normal LSP comms.

So I suspected that what's happening here is that vim-lsp probably detected an error earlier in the stdout stream, and it killed pylsp as the stream is corrupted.

So, I ran pylsp again under a debugger, and this time, I set --log-file to a logfile:

$ pylsp -vv --tcp --port 8772 --log-file /tmp/log.txt   ## 11:57:35
Daemon is up and running

and there we go, this string comes from dmypy.

When running on tcp mode, all output should have been written to the logfile, nothing should have been in the stdout stream as that would indicate that this string would have got written into the message stream between pylsp and vim-lsp and corrupted them.

So, one of two things need to happen:

  1. Either dmypy should remove the offending output and print them to stderr, but dmypy seems to regularly prints these kind of diagnostic messages on stderr and it has been doing that since forever with no issue.
  2. Or, pylsp-mypy should capture/suppress output from dmypy

Why is there a dmypy process running if you set it to false?

Apologies for that red herring, that was dmypy from a prior run. If I killed everything first, and then started in dmypy mode, then dmypy is not started. When dmypy mode is enabled, pylsp died, but the dmypy process continues to run in the background.

Do you have anything else installed, that might interact with dmypy?

No, pylsp is the only component using d/mypy.

Do you have your development venv active?

Yes, all tests run with venv activate on the shell before starting vim.

What does which dmypy return?

It's the virtualenv's dmypy:

/home/lieryan/.virtualenvs/dmypy-test/bin/dmypy