Skip to content

Vim hangs mid-completion when used with channel-based listener_add callback #4493

Closed
Closed
Vim hangs mid-completion when used with channel-based listener_add callback#4493

Description

@myitcv
myitcv
opened on Jun 5, 2019

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.go initially populated with:

package main

func main() {
	mai
}

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:

package main

func main() {
	main
}

The sequence from the Vim channel log corresponding to this is:

  2.274961 SEND on 0(in): '[32,["function","function:GOVIM_internal_Complete",[1,""]]]
'
  2.275044 on 0: Reading JSON
  2.275056 : looking for messages on channels
  2.275062 on 0: Waiting for up to 30000 msec
  2.275680 RECV on 0(out): '[0,[26,"expr","{\"bufnum\": bufnr(\"\"), \"line\": line(\".\"), \"col\": col(\".\")}"]]
'
  2.275698 : looking for messages on channels
  2.275755 on 0: Getting JSON message 0
  2.275769 on 0: Invoking channel callback <SNR>46_define
  2.275963 SEND on 0(in): '[33,["callback",26,["",{"bufnum":1,"col":5,"line":4}]]]
'
  2.276028 : looking for messages on channels
  2.276040 on 0: Waiting for up to 30000 msec
  2.287999 RECV on 0(out): '[32,["",1]]
'
  2.288016 on 0: Getting JSON message 32
  2.288228 SEND on 0(in): '[34,["function","function:GOVIM_internal_Complete",[0,"mai"]]]
'
  2.288256 on 0: Reading JSON
  2.288262 : looking for messages on channels
  2.288264 on 0: Waiting for up to 30000 msec
  2.288571 RECV on 0(out): '[34,["",[{"abbr":"main()","word":"main","info":""}]]]
'
  2.288581 on 0: Getting JSON message 34
  2.288756 SEND on 0(in): '[35,["function","function:GOVIM_internal_BufChanged",[1,4,5,0,[{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":5,"added":0,"end":5,"lines":["\tmain"]}]]]]
'
  2.288795 on 0: Reading JSON
  2.288800 : looking for messages on channels
  2.288803 on 0: Waiting for up to 30000 msec
  2.289967 RECV on 0(out): '[35,["",null]]
'
  2.289991 on 0: Getting JSON message 35
  2.292119 SEND on 0(in): '[36,["function","function:GOVIM_internal_BufChanged",[1,4,5,0,[{"lnum":4,"col":5,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tmain"]},{"lnum":4,"col":5,"added":0,"end":5,"lines":["\tmain"]}]]]]
'
  2.292177 on 0: Reading JSON
  2.292200 : looking for messages on channels
  2.292209 on 0: Waiting for up to 30000 msec
  2.293328 RECV on 0(out): '[36,["",null]]
'
  2.293358 on 0: Getting JSON message 36
  2.296341 : looking for messages on channels

Note:

  • two callbacks to the single listener_add callback
  • each called with multiple, identical changes

Otherwise, All is well at this point.

If, still in insert mode, we now hit backspace to remove the n on line 4, all is fine: we see the following in the Vim channel log:

  3.130369 SEND on 0(in): '[37,["function","function:GOVIM_internal_BufChanged",[1,4,5,0,[{"lnum":4,"col":5,"added":0,"end":5,"lines":["\tmai"]},{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tmai"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tmai"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tmai"]},{"lnum":4,"col":2,"added":0,"end":5,"lines":["\tmai"]},{"lnum":4,"col":3,"added":0,"end":5,"lines":["\tmai"]},{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tmai"]}]]]]
'
  3.130454 on 0: Reading JSON
  3.130467 : looking for messages on channels
  3.130473 on 0: Waiting for up to 30000 msec
  3.132323 RECV on 0(out): '[37,["",null]]
'
  3.132343 on 0: Getting JSON message 37
  3.134817 : looking for messages on channels

All is still well at this point.

If we then hit backspace again, the following sequence occurs:

  5.571337 SEND on 0(in): '[38,["function","function:GOVIM_internal_Complete",[1,""]]]
'
  5.571422 on 0: Reading JSON
  5.571434 : looking for messages on channels
  5.571440 on 0: Waiting for up to 30000 msec
  5.572045 RECV on 0(out): '[0,[27,"expr","{\"bufnum\": bufnr(\"\"), \"line\": line(\".\"), \"col\": col(\".\")}"]]
'
  5.572064 : looking for messages on channels
  5.572086 on 0: Getting JSON message 0
  5.572092 on 0: Invoking channel callback <SNR>46_define
  5.572284 SEND on 0(in): '[39,["callback",27,["",{"bufnum":1,"col":4,"line":4}]]]
'
  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"]}]]]]
'
  5.572784 on 0: Reading JSON
  5.572789 : looking for messages on channels
  5.572793 on 0: Waiting for up to 30000 msec
  5.574954 RECV on 0(out): '[38,["",1]]
'
  5.574977 : looking for messages on channels
  5.575034 on 0: Getting JSON message 38
  5.575044 on 0: Dropping message 38 without callback
  5.575049 : looking for messages on channels
  5.575055 on 0: Waiting for up to 30000 msec
  5.575830 RECV on 0(out): '[40,["",null]]
'
  5.575845 on 0: Getting JSON message 40
  5.575955 : looking for messages on channels
  5.576027 on 0: Waiting for up to 30000 msec
  • Vim sends a completion request (which is handled by the channel-based govim)
  • as part of handling this request, a call is made back to Vim for the cursor position
  • the cursor position response is received by govim
  • Vim triggers a callback to a listener_add function (this is also channel-based in govim) - notice again the many repeated but identical changes
  • govim responds to the findstart half of the completion request with the column number
  • govim returns from the listener_add callback function

Vim then hangs, only for 30 secs later (I have my channel timeout at 30secs so this corresponds):

 35.587927 on 0: Timed out
 35.588509 SEND on 0(in): '[41,["function","function:GOVIM_internal_Complete",[0,"\tma"]]]
'
 35.588638 on 0: Reading JSON
 35.588679 : looking for messages on channels
 35.588765 on 0: Waiting for up to 30000 msec
 35.589272 RECV on 0(out): '[41,["",[{"abbr":"main()","word":"main","info":""},{"abbr":"make(t Type, size ...int)","word":"make","info":"Type"}]]]
'
 35.589295 on 0: Getting JSON message 41
 35.589759 SEND on 0(in): '[42,["function","function:GOVIM_internal_BufChanged",[1,4,5,0,[{"lnum":4,"col":4,"added":0,"end":5,"lines":["\tma{\u0001V"]},{"lnum":4,"col":5,"added":0,"end":5,"lines":["\tma{\u0001V"]},{"lnum":4,"col":6,"added":0,"end":5,"lines":["\tma{\u0001V"]}]]]]
'
 35.589903 on 0: Reading JSON
 35.589979 : looking for messages on channels
 35.590039 on 0: Waiting for up to 30000 msec
 35.591493 RECV on 0(out): '[42,["",null]]
'
 35.591551 on 0: Getting JSON message 42
 35.592308 : looking for messages on channels

govim does 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):

  • Vim version
VIM - Vi IMproved 8.1 (2018 May 18, compiled Jun  5 2019 11:02:31)
Included patches: 1-1467
Compiled by myitcv@myitcv
Huge version with GTK2 GUI.  Features included (+) or not (-):
+acl               +extra_search      +mouse_netterm     -tag_old_static
+arabic            -farsi             +mouse_sgr         -tag_any_white
+autocmd           +file_in_path      -mouse_sysmouse    -tcl
+autochdir         +find_in_path      +mouse_urxvt       +termguicolors
-autoservername    +float             +mouse_xterm       +terminal
+balloon_eval      +folding           +multi_byte        +terminfo
+balloon_eval_term -footer            +multi_lang        +termresponse
+browse            +fork()            -mzscheme          +textobjects
++builtin_terms    +gettext           -netbeans_intg     +textprop
+byte_offset       -hangul_input      +num64             +timers
+channel           +iconv             +packages          +title
+cindent           +insert_expand     +path_extra        +toolbar
+clientserver      +job               -perl              +user_commands
+clipboard         +jumplist          +persistent_undo   +vartabs
+cmdline_compl     +keymap            +postscript        +vertsplit
+cmdline_hist      +lambda            +printer           +virtualedit
+cmdline_info      +langmap           +profile           +visual
+comments          +libcall           +python            +visualextra
+conceal           +linebreak         -python3           +viminfo
+cryptv            +lispindent        +quickfix          +vreplace
+cscope            +listcmds          +reltime           +wildignore
+cursorbind        +localmap          +rightleft         +wildmenu
+cursorshape       +lua               -ruby              +windows
+dialog_con_gui    +menu              +scrollbind        +writebackup
+diff              +mksession         +signs             +X11
+digraphs          +modify_fname      +smartindent       -xfontset
+dnd               +mouse             +startuptime       +xim
-ebcdic            +mouseshape        +statusline        +xpm
+emacs_tags        +mouse_dec         -sun_workshop      +xsmp_interact
+eval              -mouse_gpm         +syntax            +xterm_clipboard
+ex_extra          -mouse_jsbterm     +tag_binary        -xterm_save
   system vimrc file: "$VIM/vimrc"
     user vimrc file: "$HOME/.vimrc"
 2nd user vimrc file: "~/.vim/vimrc"
      user exrc file: "$HOME/.exrc"
  system gvimrc file: "$VIM/gvimrc"
    user gvimrc file: "$HOME/.gvimrc"
2nd user gvimrc file: "~/.vim/gvimrc"
       defaults file: "$VIMRUNTIME/defaults.vim"
    system menu file: "$VIMRUNTIME/menu.vim"
  fall-back for $VIM: "/home/myitcv/usr/vim/share/vim"
Compilation: gcc -c -I. -Iproto -DHAVE_CONFIG_H -DFEAT_GUI_GTK  -pthread -I/usr/include/gtk-2.0 -I/usr/lib/x86_64-linux-gnu/gtk-2.0/include -I/usr/include/gio-unix-2.0 -I/usr/include/cairo -I/usr/include/pango-1.0 -I/usr/include/atk-1.0 -I/usr/include/cairo -I/usr/include/pixman-1 -I/usr/include/gdk-pixbuf-2.0 -I/usr/include/libmount -I/usr/include/blkid -I/usr/include/pango-1.0 -I/usr/include/harfbuzz -I/usr/include/pango-1.0 -I/usr/include/fribidi -I/usr/include/glib-2.0 -I/usr/lib/x86_64-linux-gnu/glib-2.0/include -I/usr/include/uuid -I/usr/include/freetype2 -I/usr/include/libpng16   -g -O2 -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=1       
Linking: gcc   -L/usr/local/lib -Wl,--as-needed -o vim   -lgtk-x11-2.0 -lgdk-x11-2.0 -lpangocairo-1.0 -latk-1.0 -lcairo -lgdk_pixbuf-2.0 -lgio-2.0 -lpangoft2-1.0 -lpango-1.0 -lgobject-2.0 -lglib-2.0 -lfontconfig -lfreetype -lSM -lICE -lXpm -lXt -lX11 -lXdmcp -lSM -lICE  -lm -ltinfo -lnsl   -ldl  -L/usr/lib/x86_64-linux-gnu -lluajit-5.1  -L/home/myitcv/.pythons/2.7.15/lib/python2.7/config -lpython2.7 -lpthread -ldl -lutil -lm -Xlinker -export-dynamic
  • OS: Ubuntu 19.04
  • Terminal: XTerm(330)

Additional context
Add any other context about the problem here.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions