Closed myitcv closed 5 years ago
brammool
commented
5 years ago This is too complicated to debug. Please add some debug statements to find out where those duplicated changes come from (they might actually be valid and caused by autocompletion), and where the hang is happening.
myitcv
commented
5 years ago This is too complicated to debug
Agreed.
First, the good news. I just realised the multiple changes are not actually identical; they differ in the 'col' value (which is not of interest to me, hence my eye skipped over that detail). So the calls to the listener_add callback function look ok, including the multiple changes. Updated the description to reflect this.
I further managed to bisect the hang issue I'm seeing to the following setting in my .vimrc:
set bs=2With set bs=2, I can recreate the hang as described above. What's important about that setup is:
omnifunclistener_add callbackWithout that setting (which I think is a default of set bs=) I cannot reproduce the hang.
Using the simple .vimrc at the end of this comment which simulates a non-channel based omnifunc and listener_add callback I can't reproduce the hang, either with set bs=2 or otherwise.
So it seems that the hang is some function of the fact govim has channel based omnifunc and listener_add callbacks. The only thing I noticed from my report in the description above is that the listener_add callback is called concurrently with the completion function:
First the completion function is triggered:
5.571337 SEND on 0(in): '[38,["function","function:GOVIM_internal_Complete",[1,""]]]then the listener_add callback is called:
5.572761 SEND on 0(in): '[40,["function","function:GOVIM_internal_BufChanged",[1,4,5,0,[{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tma"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tma"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tma"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tma"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tma"]}]]]]then the completion function returns:
5.574954 RECV on 0(out): '[38,["",1]]then the listener_add callback returns:
5.575830 RECV on 0(out): '[40,["",null]]I don't know whether that is significant or not, but such a scenario is obviously impossible in the VimScript based setup that follows.
set nocp
set noswapfile
set completeopt=menu,longest
set bs=2
function DoComplete(findstart, base)
if a:findstart == 1
return 0
else
if a:base == "mai"
return [{"abbr":"main()","word":"main","info":""}]
elseif a:base == "ma"
return [{"abbr":"main()","word":"main","info":""},{"abbr":"make(t Type, size ...int)","word":"make","info":"Type"}]
endif
endif
endfunction
set omnifunc=DoComplete
function EchoChanges(bufnr, start, end, added, changes)
redir >> /tmp/listener.log | echom a:changes | redir END
endfunction
call listener_add("EchoChanges")Just to make precise a finding in the previous comment:
govim setup is triggered when the 'backspace' setting includes the start valuelistener_add callback happening "at the same time" occurs because I'm hitting <BS> to delete a character from a completed identifier. This hang does not happen when I initiate the original completion via <C-X><C-o> (a key combination which does not cause a change)myitcv
commented
5 years ago I now have a minimal reproduction of this, outside of govim.
Key finding is that this "hang" is triggered by the channel-based complete function synchronously calling back into Vim before it (the complete function) returns.
The reproduction files can be found in the following gist:
https://gist.github.com/myitcv/f968c2f9f073121675ca44699d42fae4
Requires a working Go installation: https://golang.org/dl/
Run with:
$ vi -u complete.vimThen:
i)mai<C-x><C-o> - this should leave the first line reading mainn - this should leave the first line reading maii - this should leave the first line reading maNotice at this point that Vim has hung, and will continue to hang until the 30 sec channel timeout is triggered.
See my resulting /tmp/vim_channel.log here: https://gist.github.com/myitcv/2c9644def065e80a4ce3ba155778690c
brammool
commented
5 years ago I now have a minimal reproduction of this, outside of
govim.Key finding is that this "hang" is triggered by the channel-based complete function synchronously calling back into Vim before it (the complete function) returns.
The reproduction files can be found in the following gist:
https://gist.github.com/myitcv/f968c2f9f073121675ca44699d42fae4
Requires a working Go installation: https://golang.org/dl/
Run with:
$ vi -u complete.vimThen:
- enter insert mode (
i)- type
mai- trigger omni-complete via
<C-x><C-o>- this should leave the first line readingmain- still in insert mode, hit backspace to remove the
n- this should leave the first line readingmai- still in insert mode, hit backspace to remove the
i- this should leave the first line readingmaNotice at this point that Vim has hung, and will continue to hang until the 30 sec channel timeout is triggered.
See my resulting
/tmp/vim_channel.loghere: https://gist.github.com/myitcv/2c9644def065e80a4ce3ba155778690c
I'm trying to understand what happens exactly. It seems that the response to message 9 is dropped instead of handled:
This must result from the ch_evalexpr() call: 2.868934 SEND on 0(in): '[9,{"Comment":"Complete findstart","Calls":[["redraw",""]],"Delay":"100ms"}]
And it gets back the response about 100 msec later: 2.969833 RECV on 0(out): '[9,""]
But then: 2.969884 on 0: Getting JSON message 9 2.969893 on 0: Dropping message 9 without callback
It appears channel_read_json_block() is used recursively, and then ch_block_id is overwritten. This function was never written to handle a recursive call.
This happens because you made your server send a "redraw" while Vim is in channel_read_json_block(), and this redraw triggers invoking listener callbacks, which then does another ch_evalexpr().
I suppose the solution is to make channel_read_json_block() work resursively. You could work around it by avoiding ch_evalexpr() in the listener callback, use an asynchronous ch_sendexpr() and another callback.
Making a test for this is very tricky, since it is so timing sensitive. Thus I'll just fix the problem, and let you verify it.
-- The coffee just wasn't strong enough to defend itself -- Tom Waits
/// Bram Moolenaar -- Bram@Moolenaar.net -- http://www.Moolenaar.net \\ /// sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ \\ \\ an exciting new programming language -- http://www.Zimbu.org /// \\ help me help AIDS victims -- http://ICCF-Holland.org ///
myitcv
commented
5 years ago I suppose the solution is to make channel_read_json_block() work resursively
I think so, yes. Because otherwise, at least (selfishly) from my perspective/understanding, it makes things much harder to work with/reason about.
Making a test for this is very tricky, since it is so timing sensitive. Thus I'll just fix the problem, and let you verify it.
Totally fine with that.
govim has fairly good integration tests, so we'd likely run into any issues quite quickly.
The logging we get from the Vim channel logs and govim makes tracking these things down relatively straightforward without need for further debugging statements etc. It's creating minimal reproductions which, as you say, is so much harder.
myitcv
commented
5 years ago
Describe the bug
This was spotted in the context of
govim- I haven't managed to find a smaller reproduction.The setup is as follows,
main.goinitially populated with:We are in insert mode, with the cursor at position
(4,5).Now we trigger the omnifunc with
<C-x><C-o>; in the context this results in a single completion result,main, which duly completes to give us:The sequence from the Vim channel log corresponding to this is:
~Note:~
listener_addcallback~~Otherwise,~ All is well at this point.
If, still in insert mode, we now hit backspace to remove the
non line 4, all is fine: we see the following in the Vim channel log:All is still well at this point.
If we then hit backspace again, the following sequence occurs:
govim)govimlistener_addfunction (this is also channel-based ingovim) - ~notice again the many repeated but identical changes~govimresponds to the findstart half of the completion request with the column numbergovimreturns from thelistener_addcallback functionVim then hangs, only for 30 secs later (I have my channel timeout at 30secs so this corresponds):
govimdoes not appear to be waiting/doing anything during this 30sec period; it seems that Vim is waiting on something... but it's unclear to me what that is.Full log can be found at https://gist.github.com/myitcv/b99443a1e597898a2978af9e25f6206f
To Reproduce
I can reproduce this using
govim; I haven't managed to find a smaller repro.Expected behavior
No hang.
Screenshots
If applicable, copy/paste the text or add screenshots to help explain your problem.
Environment (please complete the following information):
Additional context Add any other context about the problem here.