Python process get defunct for seconds when restarted inside

[ysolis]

Problems summary

I am using NeoVim 1.5 and use this when i do python programming. The python process invoked for deoplete-jedi get defunct, Deoplete continue to work but i don't get any suggestion for python autocomplete almost all the times for several seconds.

Expected

The python autocomplete must continue normally.

Environment Information

• OS: Ubuntu 16.04 LTS
• Neovim version: neovim 0.1.5ubuntu1+git201609060743+27 from NeoVim PPA.

Provide a minimal init.vim with less than 50 lines (Required!)

" Your minimal init.vim
set runtimepath+=~/tmp/deoplete.nvim/
set runtimepath+=~/tmp/deoplete-jedi/
let g:deoplete#enable_at_startup = 1
set completeopt=menu,preview

The reproduce ways from neovim starting (Required!)

1. configure vim with option

   set completeopt=menu,preview

2. edit your code and wait that a preview window appear
3. check your process (pgrep -af python) you can find that the python process using jedi, invoked from deoplete is in defunct state

[Shougo]

I cannot reproduce the problem.

[ysolis]

how is restarted the python process in deoplete-jedi ?

[ysolis]

I check again the process. The python process launched for deoplete-jedi get in zombie mode, and after this get killed and a new process is created. So I assume that is restarted the process. But take some time to get completed the restart process. We can close this but we need to set an option to define how is restarted deoplete-jedi.

[zchee]

@ysolis sorry late reply. and thanks information.
Yes, maybe deoplete-jedi daemon have a bug.
I understand half, will read and understand tomorrow(now Japan is AM 4:30)
But it might be good information. Thanks.

[blueyed]

@ysolis
Maybe you can produce a log with more info?!

call deoplete#custom#set('jedi', 'debug_enabled', 1)
call deoplete#enable_logging('DEBUG', '/tmp/deoplete.log')

Also try export NVIM_PYTHON_LOG_FILE=/tmp/nvim-python-log NVIM_PYTHON_LOG_LEVEL=DEBUG before starting Neovim.

[zchee]

@blueyed Thanks. You're right.

[blueyed]

@zchee
Not sure about the method, but were just using this myself to debug Shougo/deoplete.nvim#336. (I/we should / will create a separate issue for that.)
See #60 for an improved issue template.

[ysolis]

https://gist.github.com/ysolis/9af49c1e2afa7c8e873719e0418f11ad

log uploaded and attached

[blueyed]

Thanks!

Relevant part where it starts to misbehave:

2016-09-21 09:07:54,149 DEBUG    (deoplete.jedi.Thread-1) Worker error
Traceback (most recent call last):
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/worker.py", line 67, in run
    self.out_queue.put(self.completion_work(*work), block=False)
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/worker.py", line 34, in completion_work
    filename)
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py", line 532, in completions
    return stream_read(self._server.stdout)
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py", line 83, in stream_read
    raise StreamEmpty
deoplete_jedi.server.StreamEmpty
2016-09-21 09:07:57,698 DEBUG    (deoplete.jedi.cache) Input: "i"
2016-09-21 09:07:57,699 DEBUG    (deoplete.jedi) Key: ('add4d4c65ffb2275f5a0bfdc9c72543b', ('views', 'unique'), 'vars'), Refresh: True, Wait: False
2016-09-21 09:07:57,701 INFO     (deoplete.jedi) �[34mgather_candidates�[m t = �[32m6.441123�[mms, µ = �[39m16.541704�[mms, σ = �[39m23.852977�[mms)
2016-09-21 09:07:57,707 DEBUG    (deoplete.jedi.Thread-1) Got work
2016-09-21 09:07:57,708 DEBUG    (deoplete.jedi.Thread-1) Worker error
Traceback (most recent call last):
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/worker.py", line 67, in run
    self.out_queue.put(self.completion_work(*work), block=False)
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/worker.py", line 34, in completion_work
    filename)
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py", line 531, in completions
    stream_write(self._server.stdin, args)
  File "/home/yonsy/.config/nvim/dein/repos/github.com/zchee/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py", line 101, in stream_write
    pipe.flush()
BrokenPipeError: [Errno 32] Broken pipe

The StreamEmpty gets raised in stream_read (called in Client.completions): https://github.com/zchee/deoplete-jedi/blob/ba6c29144f69ede846ebc3a7e4000eed5f5a76a6/rplugin/python3/deoplete/sources/deoplete_jedi/server.py#L532.

It is not caught there, like it's done in the Server's _loop.

@ysolis
Can you try #65, please?

Can you reliably trigger the crash?

You wrote:

edit your code and wait that a preview window appear

For me it does not crash the Python process, but that might be related to the code/preview?

Can you provide a small snippet to reproduce it, too?

(Looking at that made me find the fix for #61: #63 (AFAICS).)

[ysolis]

@blueyed the preview window is not relevant, i think that was the initial case but no, the problem happens with or without preview window.

[blueyed]

@ysolis
So how do you trigger the crash then?
Have you tried #65?

[ysolis]

i do a pgrep python when i invoke neovim, i can see the python process called for deoplete and deoplete-jedi. After some time i can check the pid for the python process called by deoplete-jedi and i see that is in zombie mode (defunct) after some minutes get restarted.

i will try #65 in one hour.

[blueyed]

After some time i can check the pid for the python process called by deoplete-jedi and i see that is in zombie mode (defunct)

It would be useful to have the debug log(s) when this happens. With #65 there should be a bit more logging for example.

[ysolis]

#65 tried ... and the python process that is launched from deoplete-jedi don't go to zombie and defunct in the restart, get restarted without any problem

check my pgrep report:

(analysis) ~/devops/analysis   master  pgrep -af python
22347 /usr/bin/python3.5 -c import sys; sys.path.remove(""); import neovim; neovim.start_host() /home/yonsy/.config/nvim/dein/.dein/rplugin/python3/deoplete
22461 /home/yonsy/.pyenv/versions/pypy2-5.4.1/envs/analysis/bin/python -u /home/yonsy/.config/nvim/dein/repos/github.com/blueyed/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py --desc-length 0
(analysis) ~/devops/analysis   master  pgrep -af python
22347 /usr/bin/python3.5 -c import sys; sys.path.remove(""); import neovim; neovim.start_host() /home/yonsy/.config/nvim/dein/.dein/rplugin/python3/deoplete
24248 /home/yonsy/.pyenv/versions/pypy2-5.4.1/envs/analysis/bin/python -u /home/yonsy/.config/nvim/dein/repos/github.com/blueyed/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py --desc-length 0
(analysis) ~/devops/analysis   master 

the first one was when i open a *.py file. the second one was after i edit the same file and add some python code in few minutes. Previously the python process invoked for deoplete-jedi get defunct before get restarted, and in this time the plugin don't work (no python completion, only name completion). With #65 the process get restarted and the edition and python completion don't get affected, work flawlessly.

[ysolis]

https://gist.github.com/ysolis/619bdaf13da14781f0672856156e92b5